Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Thu, Jun 25, 2020 at 10:00:09AM +0800, Nicolas Boichat wrote:
> On Thu, Jun 25, 2020 at 1:25 AM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Wed, Jun 24, 2020 at 9:07 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Wed, 24 Jun 2020 16:45:24 +0800
> > > Nicolas Boichat <drinkcat@chromium.org> wrote:
> > >
> > > > trace_printk is only meant as a debugging tool, and should never be
> > > > compiled into production code without source code changes, as
> > > > indicated by the warning that shows up on boot if any trace_printk
> > > > is called:
> > > >  **   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
> > > >  **                                                      **
> > > >  ** trace_printk() being used. Allocating extra memory.  **
> > > >  **                                                      **
> > > >  ** This means that this is a DEBUG kernel and it is     **
> > > >  ** unsafe for production use.                           **
> > > >
> > > > If this option is set to n, the kernel will generate a build-time
> > > > error if trace_printk is used.
> > > >
> > > > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
> > >
> > > Interesting. Note, this will prevent modules with trace_printk from
> > > being loaded as well.
> >
> > Nack.
> > The message is bogus. It's used in production kernels.
> > bpf_trace_printk() calls it.
> 
> Interesting. BTW, the same information (trace_printk is for debugging
> only) is repeated all over the place, including where bpf_trace_printk
> is documented:
> https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> 
> Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> when trace_printk() is in use")), so maybe he can confirm if it's
> still relevant.

The banner is nasty and it's actively causing harm.
Every few month I have to explain to users that it's absolulte ok to
ignore that banner. Nothing bad is happening with the kernel.
The kernel is still perfectly safe for production use.
It's not a debug kernel.

What bpf_trace_printk() doc is saying that it's not recommended to use
this helper for production bpf programs. There are better alternatives.
It is absolutely fine to use bpf_trace_printk() to debug production and
experimental bpf programs on production servers, android phones and
everywhere else.

> Also, note that emitting the build error is behind a Kconfig option,
> you don't have to select it if you don't want to (the default is =y
> which allows trace_printk).
> 
> If the overhead is real, we (Chrome OS) would like to make sure
> trace_printk does not slip into production kernels (we do want to
> provide basic tracing support so we can't just remove CONFIG_TRACING
> as a whole which would make trace_printk no-ops). I could also imagine
> potential security issues if people print raw pointers/sensitive data
> in trace_printk, assuming that the code is for debugging only.
> 
> Also, the fact that the kernel test robot already found a stray
> trace_printk in drivers/usb/cdns3/gadget.c makes me think that this
> change is working as intended ,-) (we're going to need to add a few
> Kconfig deps though for other debugging options that intentionally use
> trace_printk).

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Wed, 24 Jun 2020 20:59:13 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > >
> > > Nack.

I nack your nack ;-)

> > > The message is bogus. It's used in production kernels.
> > > bpf_trace_printk() calls it.  
> > 
> > Interesting. BTW, the same information (trace_printk is for debugging
> > only) is repeated all over the place, including where bpf_trace_printk
> > is documented:
> > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > 
> > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > when trace_printk() is in use")), so maybe he can confirm if it's
> > still relevant.  
> 
> The banner is nasty and it's actively causing harm.

And it's doing exactly what it was intended on doing!

> Every few month I have to explain to users that it's absolulte ok to
> ignore that banner. Nothing bad is happening with the kernel.
> The kernel is still perfectly safe for production use.
> It's not a debug kernel.
> 
> What bpf_trace_printk() doc is saying that it's not recommended to use
> this helper for production bpf programs. There are better alternatives.
> It is absolutely fine to use bpf_trace_printk() to debug production and
> experimental bpf programs on production servers, android phones and
> everywhere else.

Now I do have an answer for you that I believe is a great compromise.

There's something you can call (and even call it from a module). It's
called "trace_array_vprintk()". But has one caveat, and that is, you
can not write to the main top level trace buffer with it (I have
patches for the next merge window to enforce that). And that's what
I've been trying to avoid trace_printk() from doing, as that's what it
does by default. It writes to /sys/kernel/tracing/trace.

Now what you can do, is have bpf create
a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
trace_array_printk(), to print into that, and you will never have to
see that warning again! It shows up in your own
tracefs/instances/bpf_trace/trace file!

If you need more details, let me know, and I can give you all you need
to know to create you very own trace instance (that can enable events,
kprobe events, uprobe events, function tracing, and soon function graph
tracing). And the bonus, you get trace_array_vprintk() and no more
complaining. :-) :-) :-)

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Fri, Jun 26, 2020 at 06:14:55PM -0400, Steven Rostedt wrote:
> On Wed, 24 Jun 2020 20:59:13 -0700
> Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> 
> > > >
> > > > Nack.
> 
> I nack your nack ;-)

ok. let's take it up to Linus to decide.

> 
> > > > The message is bogus. It's used in production kernels.
> > > > bpf_trace_printk() calls it.  
> > > 
> > > Interesting. BTW, the same information (trace_printk is for debugging
> > > only) is repeated all over the place, including where bpf_trace_printk
> > > is documented:
> > > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > > 
> > > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > > when trace_printk() is in use")), so maybe he can confirm if it's
> > > still relevant.  
> > 
> > The banner is nasty and it's actively causing harm.
> 
> And it's doing exactly what it was intended on doing!

I disagree. The message is _lying_ about the state of the kernel.
It's not a debug kernel and it's absolutely fine for production.

> > Every few month I have to explain to users that it's absolulte ok to
> > ignore that banner. Nothing bad is happening with the kernel.
> > The kernel is still perfectly safe for production use.
> > It's not a debug kernel.
> > 
> > What bpf_trace_printk() doc is saying that it's not recommended to use
> > this helper for production bpf programs. There are better alternatives.
> > It is absolutely fine to use bpf_trace_printk() to debug production and
> > experimental bpf programs on production servers, android phones and
> > everywhere else.
> 
> Now I do have an answer for you that I believe is a great compromise.
> 
> There's something you can call (and even call it from a module). It's
> called "trace_array_vprintk()". But has one caveat, and that is, you
> can not write to the main top level trace buffer with it (I have
> patches for the next merge window to enforce that). And that's what
> I've been trying to avoid trace_printk() from doing, as that's what it
> does by default. It writes to /sys/kernel/tracing/trace.
> 
> Now what you can do, is have bpf create
> a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
> trace_array_printk(), to print into that, and you will never have to
> see that warning again! It shows up in your own
> tracefs/instances/bpf_trace/trace file!
> 
> If you need more details, let me know, and I can give you all you need
> to know to create you very own trace instance (that can enable events,
> kprobe events, uprobe events, function tracing, and soon function graph
> tracing). And the bonus, you get trace_array_vprintk() and no more
> complaining. :-) :-) :-)

We added a bunch of code to libbcc in the past to support instances,
but eventually removed it all due to memory overhead per instance.
If I recall it was ~8Mbyte per instance. That was couple years ago.

By now everyone has learned to use bpf_trace_printk() and expects
to see the output in /sys/kernel/debug/tracing/trace.
It's documented in uapi/bpf.h and various docs.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 10:27:00 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> On Fri, Jun 26, 2020 at 06:14:55PM -0400, Steven Rostedt wrote:
> > On Wed, 24 Jun 2020 20:59:13 -0700
> > Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> >   
> > > > >
> > > > > Nack.  
> > 
> > I nack your nack ;-)  
> 
> ok. let's take it up to Linus to decide.

I'm fine with that.

> 
> >   
> > > > > The message is bogus. It's used in production kernels.
> > > > > bpf_trace_printk() calls it.    
> > > > 
> > > > Interesting. BTW, the same information (trace_printk is for debugging
> > > > only) is repeated all over the place, including where bpf_trace_printk
> > > > is documented:
> > > > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > > > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > > > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > > > 
> > > > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > > > when trace_printk() is in use")), so maybe he can confirm if it's
> > > > still relevant.    
> > > 
> > > The banner is nasty and it's actively causing harm.  
> > 
> > And it's doing exactly what it was intended on doing!  
> 
> I disagree. The message is _lying_ about the state of the kernel.
> It's not a debug kernel and it's absolutely fine for production.

No it is not!

It causes the trace buffer to be filled with crap that can not be
easily disabled. That's the reason I only allowed trace_printk() for
debug kernels. And the only way to prevent people from sticking it in
their code and making an API out of it was for this banner.

I refuse to remove that banner. It's my API!

> > 
> > Now I do have an answer for you that I believe is a great compromise.
> > 
> > There's something you can call (and even call it from a module). It's
> > called "trace_array_vprintk()". But has one caveat, and that is, you
> > can not write to the main top level trace buffer with it (I have
> > patches for the next merge window to enforce that). And that's what
> > I've been trying to avoid trace_printk() from doing, as that's what it
> > does by default. It writes to /sys/kernel/tracing/trace.
> > 
> > Now what you can do, is have bpf create
> > a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
> > trace_array_printk(), to print into that, and you will never have to
> > see that warning again! It shows up in your own
> > tracefs/instances/bpf_trace/trace file!
> > 
> > If you need more details, let me know, and I can give you all you need
> > to know to create you very own trace instance (that can enable events,
> > kprobe events, uprobe events, function tracing, and soon function graph
> > tracing). And the bonus, you get trace_array_vprintk() and no more
> > complaining. :-) :-) :-)  
> 
> We added a bunch of code to libbcc in the past to support instances,
> but eventually removed it all due to memory overhead per instance.
> If I recall it was ~8Mbyte per instance. That was couple years ago.

I'd like to see where that 8 MB per instance came from. You can control
the size of the instance buffers. If size is still an issue, I'll be
happy to work with you to fix it.


> 
> By now everyone has learned to use bpf_trace_printk() and expects
> to see the output in /sys/kernel/debug/tracing/trace.
> It's documented in uapi/bpf.h and various docs.

Re-teach them, or are you finally admitting that the tracing system is
a permanent API?  This is the reason people are refusing to add trace
points into their subsystems. Because user space may make it required.

I see no reason why you can't create a dedicated BPF tracing instance
(you only need one) to add all your trace_array_printk()s to.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 14:46:16 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > We added a bunch of code to libbcc in the past to support instances,
> > but eventually removed it all due to memory overhead per instance.
> > If I recall it was ~8Mbyte per instance. That was couple years ago.  
> 
> I'd like to see where that 8 MB per instance came from. You can control
> the size of the instance buffers. If size is still an issue, I'll be
> happy to work with you to fix it.

Looks to be the duplication of the event directory tree. There's a lot
of duplicate data there. Instead of just punting and saying "instances
are too large" perhaps you could get someone to look at a way to
consolidate that data? I'm sure there's a lot of ways to help here.

Or you can just create a new event called bpf_printk() that passes in
and records a string and enable that automatically when a bpf module
has it. That could work as well.

In either case, your use of trace_printk() is an abuse of its purpose.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 02:46:16PM -0400, Steven Rostedt wrote:
> > 
> > By now everyone has learned to use bpf_trace_printk() and expects
> > to see the output in /sys/kernel/debug/tracing/trace.
> > It's documented in uapi/bpf.h and various docs.
> 
> Re-teach them, or are you finally admitting that the tracing system is
> a permanent API?  This is the reason people are refusing to add trace
> points into their subsystems. Because user space may make it required.
> 
> I see no reason why you can't create a dedicated BPF tracing instance
> (you only need one) to add all your trace_array_printk()s to.

All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.
If we do so a lot of users will complain. Loudly.
If you really want to see the flames, go ahead and rename 'trace_pipe'
into something else.
This has nothing to do with tracing in general and tracepoints.
Those come and go.
If you really want to nuke trace_printk from the kernel we need time
to work on replacement and give users at least few releases of helper
deprecation time. We've never done in the past though.
There could be flames even if we deprecate it gradually.
Looking how unyielding you're about this banner I guess we have to start
working on replacement sooner than later. Oh well.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

 On Sun, 28 Jun 2020 12:21:07 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > Re-teach them, or are you finally admitting that the tracing system is
> > a permanent API?  This is the reason people are refusing to add trace
> > points into their subsystems. Because user space may make it required.
> > 
> > I see no reason why you can't create a dedicated BPF tracing instance
> > (you only need one) to add all your trace_array_printk()s to.  
> 
> All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
> cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.

Then do a bpf trace event and enable it when a bpf_trace_printk() is
loaded. It will work the same for your users.

> If we do so a lot of users will complain. Loudly.
> If you really want to see the flames, go ahead and rename 'trace_pipe'
> into something else.

The layout of the tracefs system *is* a stable API. No argument there.

> This has nothing to do with tracing in general and tracepoints.
> Those come and go.

And in this case, trace_printk() is no different than any other trace
event. Obviously, your use case doesn't let it go. If some tool starts
relying on another trace event (say someone adds another bpf handler that
enables a trace event, and is documented) then under your scenario,
it's a stable API.

Hence, your "tracepoints come and go" is not universal, and there's no
telling which ones will end up being a stable API.


> If you really want to nuke trace_printk from the kernel we need time
> to work on replacement and give users at least few releases of helper
> deprecation time.

I never said I would nuke it. This patch in question makes it so those
that don't want that banner to ever show up can do so. A trace-printk()
is something to add via compiling. And since I and others use it
heavily for debugging, I would have this option not be a default, but
something that others can enable.

> We've never done in the past though.
> There could be flames even if we deprecate it gradually.
> Looking how unyielding you're about this banner I guess we have to start
> working on replacement sooner than later. Oh well.

Hmm, so you are happier to bully and burn bridges with me to deprecate
the trace_printk() interface, than to work with me and add an update to
look into an instance for the print instead of the top level? That's
not very collaborative.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 03:43:31PM -0400, Steven Rostedt wrote:
>  On Sun, 28 Jun 2020 12:21:07 -0700
> Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> 
> > > Re-teach them, or are you finally admitting that the tracing system is
> > > a permanent API?  This is the reason people are refusing to add trace
> > > points into their subsystems. Because user space may make it required.
> > > 
> > > I see no reason why you can't create a dedicated BPF tracing instance
> > > (you only need one) to add all your trace_array_printk()s to.  
> > 
> > All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
> > cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.
> 
> Then do a bpf trace event and enable it when a bpf_trace_printk() is
> loaded. It will work the same for your users.

I'm not sure I follow. How that would preserve the expectation
to see the output in /sys/kernel/debug/tracing/trace ?

> > If we do so a lot of users will complain. Loudly.
> > If you really want to see the flames, go ahead and rename 'trace_pipe'
> > into something else.
> 
> The layout of the tracefs system *is* a stable API. No argument there.
> 
> > This has nothing to do with tracing in general and tracepoints.
> > Those come and go.
> 
> And in this case, trace_printk() is no different than any other trace
> event. Obviously, your use case doesn't let it go. If some tool starts
> relying on another trace event (say someone adds another bpf handler that
> enables a trace event, and is documented) then under your scenario,
> it's a stable API.

not quite. Documneting kprobe+bpf as an example and writing a blog and a book
about it doesn't make it stable.

> 
> Hence, your "tracepoints come and go" is not universal, and there's no
> telling which ones will end up being a stable API.
> 
> 
> > If you really want to nuke trace_printk from the kernel we need time
> > to work on replacement and give users at least few releases of helper
> > deprecation time.
> 
> I never said I would nuke it. This patch in question makes it so those
> that don't want that banner to ever show up can do so. A trace-printk()
> is something to add via compiling. And since I and others use it
> heavily for debugging, I would have this option not be a default, but
> something that others can enable.
> 
> > We've never done in the past though.
> > There could be flames even if we deprecate it gradually.
> > Looking how unyielding you're about this banner I guess we have to start
> > working on replacement sooner than later. Oh well.
> 
> Hmm, so you are happier to bully and burn bridges with me to deprecate
> the trace_printk() interface, than to work with me and add an update to
> look into an instance for the print instead of the top level? That's
> not very collaborative.

I'm seeing it differently.
I'm saying bpf users are complaining about misleading dmesg warning.
You're saying 'screw your users I want to keep that warning'.
Though the warning is lying with a straight face. The only thing happened
is few pages were allocated that will never be freed. The kernel didn't
suddenly become non-production. It didn't become slower. No debug features
were turned on.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 15:02:09 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > 
> > Then do a bpf trace event and enable it when a bpf_trace_printk() is
> > loaded. It will work the same for your users.  
> 
> I'm not sure I follow. How that would preserve the expectation
> to see the output in /sys/kernel/debug/tracing/trace ?

You create a bpf event just like you create any other event. When a bpf
program that uses a bpf_trace_printk() is loaded, you can enable that
event from within the kernel. Yes, there's internal interfaces to
enabled and disable events just like echoing 1 into
tracefs/events/system/event/enable. See trace_set_clr_event().

Then the data of that event will appear in
the /sys/kernel/tracing/trace file just like the trace_printk does.

The difference is, if something in the kernel decides to use that
event, I can easily disable it from user space, where trace_printk() I
can't.


> > 
> > Hmm, so you are happier to bully and burn bridges with me to deprecate
> > the trace_printk() interface, than to work with me and add an update to
> > look into an instance for the print instead of the top level? That's
> > not very collaborative.  
> 
> I'm seeing it differently.
> I'm saying bpf users are complaining about misleading dmesg warning.
> You're saying 'screw your users I want to keep that warning'.
> Though the warning is lying with a straight face. The only thing happened
> is few pages were allocated that will never be freed. The kernel didn't
> suddenly become non-production. It didn't become slower. No debug features
> were turned on.

Come now Alexei. That banner was there from day one trace_printk() was
added into the kernel. YOU used this knowing damn well that banner
existed. If the bpf users should be upset with someone, it is you for
not asking me for how to do this properly from the beginning.

This is not a regression. trace_printk() always has shown this, and
when I added trace_printk() I stated this is only for debugging a
kernel, and not to be kept in mainline. That banner helped enforce
that. If I didn't do that, there would be trace_printk()s all over the
place, and there's no way to disable one without disabling all the
others. This would have made trace_printk() become useless for
debugging a kernel, as then you will have to deal with everyone's
trace_printks() adding noise to what you want to debug.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 18:28:42 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> You create a bpf event just like you create any other event. When a bpf
> program that uses a bpf_trace_printk() is loaded, you can enable that
> event from within the kernel. Yes, there's internal interfaces to
> enabled and disable events just like echoing 1 into
> tracefs/events/system/event/enable. See trace_set_clr_event().

I just started playing with what the code would look like and have
this. It can be optimized with per-cpu sets of buffers to remove the
spin lock. I also didn't put in the enabling of the event, but I'm sure
you can figure that out.

Warning, not even compiled tested.

-- Steve

diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 6575bb0a0434..aeba5ee7325a 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
 GCOV_PROFILE := y
 endif
 
+CFLAGS_bpf_trace.o := -I$(src)
+
 CFLAGS_trace_benchmark.o := -I$(src)
 CFLAGS_trace_events_filter.o := -I$(src)
 
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index dc05626979b8..01bedf335b2e 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -19,6 +19,9 @@
 #include "trace_probe.h"
 #include "trace.h"
 
+#define CREATE_TRACE_EVENTS
+#include "bpf_trace.h"
+
 #define bpf_event_rcu_dereference(p)					\
 	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
 
@@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
 		fmt_cnt++;
 	}
 
+static DEFINE_SPINLOCK(trace_printk_lock);
+#define BPF_TRACE_PRINTK_SIZE	1024
+
+static inline void do_trace_printk(const char *fmt, ...)
+{
+	static char buf[BPF_TRACE_PRINT_SIZE];
+	unsigned long flags;
+
+	spin_lock_irqsave(&trace_printk_lock, flags);
+	va_start(ap, fmt);
+	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
+	va_end(ap);
+
+	trace_bpf_trace_printk(buf);
+	spin_unlock_irqrestore(&trace_printk_lock, flags);
+}
+
 /* Horrid workaround for getting va_list handling working with different
  * argument type combinations generically for 32 and 64 bit archs.
  */
 #define __BPF_TP_EMIT()	__BPF_ARG3_TP()
 #define __BPF_TP(...)							\
-	__trace_printk(0 /* Fake ip */,					\
-		       fmt, ##__VA_ARGS__)
+	do_trace_printk(fmt, ##__VA_ARGS__)
 
 #define __BPF_ARG1_TP(...)						\
 	((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64))	\
diff --git a/kernel/trace/bpf_trace.h b/kernel/trace/bpf_trace.h
new file mode 100644
index 000000000000..09088bb92fe1
--- /dev/null
+++ b/kernel/trace/bpf_trace.h
@@ -0,0 +1,27 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM bpf_trace
+
+#if !defined(_TRACE_BPF_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_BPF_TRACE_H
+
+TRACE_EVENT(bpf_trace_printk,
+
+	TP_PROTO(bpf_string),
+
+	TP_ARGS(secs, err),
+
+	TP_STRUCT__entry(
+		__string(bpf_string, bpf_string)
+	),
+
+	TP_fast_assign(
+		__assign_string(bpf_string, bpf_string);
+	),
+
+	TP_printk("%s", __get_str(bpf_string))
+);
+
+#endif /* _TRACE_BPF_TRACE_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 07:43:34PM -0400, Steven Rostedt wrote:
> On Sun, 28 Jun 2020 18:28:42 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > You create a bpf event just like you create any other event. When a bpf
> > program that uses a bpf_trace_printk() is loaded, you can enable that
> > event from within the kernel. Yes, there's internal interfaces to
> > enabled and disable events just like echoing 1 into
> > tracefs/events/system/event/enable. See trace_set_clr_event().
> 
> I just started playing with what the code would look like and have
> this. It can be optimized with per-cpu sets of buffers to remove the
> spin lock. I also didn't put in the enabling of the event, but I'm sure
> you can figure that out.
> 
> Warning, not even compiled tested.

Thanks! I see what you mean now.

> 
> -- Steve
> 
> diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> index 6575bb0a0434..aeba5ee7325a 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
>  GCOV_PROFILE := y
>  endif
>  
> +CFLAGS_bpf_trace.o := -I$(src)

not following. why this is needed?

> +
>  CFLAGS_trace_benchmark.o := -I$(src)
>  CFLAGS_trace_events_filter.o := -I$(src)
>  
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index dc05626979b8..01bedf335b2e 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -19,6 +19,9 @@
>  #include "trace_probe.h"
>  #include "trace.h"
>  
> +#define CREATE_TRACE_EVENTS

CREATE_TRACE_POINTS ?

> +#include "bpf_trace.h"
> +
>  #define bpf_event_rcu_dereference(p)					\
>  	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
>  
> @@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
>  		fmt_cnt++;
>  	}
>  
> +static DEFINE_SPINLOCK(trace_printk_lock);
> +#define BPF_TRACE_PRINTK_SIZE	1024
> +
> +static inline void do_trace_printk(const char *fmt, ...)
> +{
> +	static char buf[BPF_TRACE_PRINT_SIZE];
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&trace_printk_lock, flags);
> +	va_start(ap, fmt);
> +	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
> +	va_end(ap);
> +
> +	trace_bpf_trace_printk(buf);
> +	spin_unlock_irqrestore(&trace_printk_lock, flags);

interesting. I don't think anyone would care about spin_lock overhead.
It's better because 'trace_bpf_trace_printk' would be a separate event
that can be individually enabled/disabled?
I guess it can work.
Thanks!

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Mon, 29 Jun 2020 22:16:59 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > 
> > Warning, not even compiled tested.  
> 
> Thanks! I see what you mean now.

Great! :-)

> 
> > 
> > -- Steve
> > 
> > diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> > index 6575bb0a0434..aeba5ee7325a 100644
> > --- a/kernel/trace/Makefile
> > +++ b/kernel/trace/Makefile
> > @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
> >  GCOV_PROFILE := y
> >  endif
> >  
> > +CFLAGS_bpf_trace.o := -I$(src)  
> 
> not following. why this is needed?

It's required in order to have the TRACE_EVENT macro magic work. More
info about it here:

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/samples/trace_events/Makefile


> 
> > +
> >  CFLAGS_trace_benchmark.o := -I$(src)
> >  CFLAGS_trace_events_filter.o := -I$(src)
> >  
> > diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> > index dc05626979b8..01bedf335b2e 100644
> > --- a/kernel/trace/bpf_trace.c
> > +++ b/kernel/trace/bpf_trace.c
> > @@ -19,6 +19,9 @@
> >  #include "trace_probe.h"
> >  #include "trace.h"
> >  
> > +#define CREATE_TRACE_EVENTS  
> 
> CREATE_TRACE_POINTS ?


Doh, yeah. I did say it wasn't even compiled tested ;-)

> 
> > +#include "bpf_trace.h"
> > +
> >  #define bpf_event_rcu_dereference(p)					\
> >  	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
> >  
> > @@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
> >  		fmt_cnt++;
> >  	}
> >  
> > +static DEFINE_SPINLOCK(trace_printk_lock);
> > +#define BPF_TRACE_PRINTK_SIZE	1024
> > +
> > +static inline void do_trace_printk(const char *fmt, ...)
> > +{
> > +	static char buf[BPF_TRACE_PRINT_SIZE];
> > +	unsigned long flags;
> > +
> > +	spin_lock_irqsave(&trace_printk_lock, flags);
> > +	va_start(ap, fmt);
> > +	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
> > +	va_end(ap);
> > +
> > +	trace_bpf_trace_printk(buf);
> > +	spin_unlock_irqrestore(&trace_printk_lock, flags);  
> 
> interesting. I don't think anyone would care about spin_lock overhead.
> It's better because 'trace_bpf_trace_printk' would be a separate event
> that can be individually enabled/disabled?
> I guess it can work.
> Thanks!

I hope this does everything you need for bpf_trace_printk. If there's
something  that's not working for you, PLEASE reach out to me and ask
what you need.

Cheers!

-- Steve