[1/1] tracing: Fix event_trace_printk loss on printk_format.

Commit Message

Mars Cheng Feb. 12, 2019, 11:41 a.m. UTC

From: Andress Kuo <[e-mail]>

If fmt on event_trace_printk is not a constant, It means that something not
guaranteed, so the compiler optimizes the fmt out, and then the
__trace_printk_fmt section is not filled. if __trace_printk_fmt is not
filled, the kernel will not allocate the special buffers needed for the
event_trace_printk() and then not shown in the file output
sys/kernel/debug/tracing/print_formats.

Adding a "__used" to the variable in the __trace_printk_fmt section on
event_trace_printk() will keep it around, even though it is set to NULL.
This will keep the string from being printed in the
sys/kernel/debug/tracing/printk_formats section.

We can also refer to commit 3debb0a9ddb1 ("tracing: Fix trace_printk()
to print when not using bprintk()")that it had similar issue on path of
trace_printk().

Signed-off-by: Andress Kuo <[e-mail]>
Signed-off-by: Mars Cheng <[e-mail]>
---
 include/linux/trace_events.h |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Comments

Steven Rostedt Feb. 13, 2019, 1:41 a.m. UTC | #1

On Tue, 12 Feb 2019 19:41:57 +0800
Mars Cheng <[e-mail]> wrote:

> From: Andress Kuo <[e-mail]>
> 
> If fmt on event_trace_printk is not a constant, It means that something not
> guaranteed, so the compiler optimizes the fmt out, and then the
> __trace_printk_fmt section is not filled. if __trace_printk_fmt is not
> filled, the kernel will not allocate the special buffers needed for the
> event_trace_printk() and then not shown in the file output
> sys/kernel/debug/tracing/print_formats.
> 
> Adding a "__used" to the variable in the __trace_printk_fmt section on
> event_trace_printk() will keep it around, even though it is set to NULL.
> This will keep the string from being printed in the
> sys/kernel/debug/tracing/printk_formats section.
> 
> We can also refer to commit 3debb0a9ddb1 ("tracing: Fix trace_printk()
> to print when not using bprintk()")that it had similar issue on path of
> trace_printk().

Honestly, I don't even remember why that macro was created. I think
it's a remnant from the creation of the trace events. I think the best
solution is just to nuke it. It shouldn't be used anymore.

I'll dig a bit deeper into the history of that macro, but I'm thinking
it shouldn't exist anymore.

[ /me returns from walking down memory lane ]

Wow, that brings back some wild memories. Yes, that macro must die, and
I wish the history of it could die along with it ;-) The horror of the
old ways I tell you. The event_trace_printk() was the original way we
displayed events! No real formatting, no parsing my userspace tools. It
was just a glamorized printk. It was called TRACE_FORMAT() which was
deprecated by today's TRACE_EVENT().

That macro should have been removed by commit b8e65554d80b4.

Please just send a patch to delete that macro. Let's not be maintaining
it. It gives me nightmares.

-- Steve

> 
> Signed-off-by: Andress Kuo <[e-mail]>
> Signed-off-by: Mars Cheng <[e-mail]>
> ---
>  include/linux/trace_events.h |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> index 8a62731..26bd7c4 100644
> --- a/include/linux/trace_events.h
> +++ b/include/linux/trace_events.h
> @@ -551,7 +551,7 @@ extern int trace_define_field(struct trace_event_call *call, const char *type,
>  	__trace_printk_check_format(fmt, ##args);			\
>  	tracing_record_cmdline(current);				\
>  	if (__builtin_constant_p(fmt)) {				\
> -		static const char *trace_printk_fmt			\
> +		static const char *trace_printk_fmt __used		\
>  		  __attribute__((section("__trace_printk_fmt"))) =	\
>  			__builtin_constant_p(fmt) ? fmt : NULL;		\
>  									\

Mars Cheng Feb. 13, 2019, 4:54 a.m. UTC | #2

Hi Steve

On Tue, 2019-02-12 at 20:41 -0500, Steven Rostedt wrote:
> On Tue, 12 Feb 2019 19:41:57 +0800
> Mars Cheng <[e-mail]> wrote:
> 
> > From: Andress Kuo <[e-mail]>
> > 
> > If fmt on event_trace_printk is not a constant, It means that something not
> > guaranteed, so the compiler optimizes the fmt out, and then the
> > __trace_printk_fmt section is not filled. if __trace_printk_fmt is not
> > filled, the kernel will not allocate the special buffers needed for the
> > event_trace_printk() and then not shown in the file output
> > sys/kernel/debug/tracing/print_formats.
> > 
> > Adding a "__used" to the variable in the __trace_printk_fmt section on
> > event_trace_printk() will keep it around, even though it is set to NULL.
> > This will keep the string from being printed in the
> > sys/kernel/debug/tracing/printk_formats section.
> > 
> > We can also refer to commit 3debb0a9ddb1 ("tracing: Fix trace_printk()
> > to print when not using bprintk()")that it had similar issue on path of
> > trace_printk().
> 
> Honestly, I don't even remember why that macro was created. I think
> it's a remnant from the creation of the trace events. I think the best
> solution is just to nuke it. It shouldn't be used anymore.
> 
> I'll dig a bit deeper into the history of that macro, but I'm thinking
> it shouldn't exist anymore.
> 
> [ /me returns from walking down memory lane ]
> 
> Wow, that brings back some wild memories. Yes, that macro must die, and
> I wish the history of it could die along with it ;-) The horror of the
> old ways I tell you. The event_trace_printk() was the original way we
> displayed events! No real formatting, no parsing my userspace tools. It
> was just a glamorized printk. It was called TRACE_FORMAT() which was
> deprecated by today's TRACE_EVENT().
> 
> That macro should have been removed by commit b8e65554d80b4.
> 
> Please just send a patch to delete that macro. Let's not be maintaining
> it. It gives me nightmares.
> 
> -- Steve

Got it, I will send another patch to remove the nightmares. :-)

Thanks.

Mars Cheng Feb. 13, 2019, 6:49 a.m. UTC | #3

Hi Steve

On Wed, 2019-02-13 at 12:54 +0800, Mars Cheng wrote:
> Hi Steve
> 
> On Tue, 2019-02-12 at 20:41 -0500, Steven Rostedt wrote:
> > On Tue, 12 Feb 2019 19:41:57 +0800
> > Mars Cheng <[e-mail]> wrote:
> > 
> > > From: Andress Kuo <[e-mail]>
> > > 
> > > If fmt on event_trace_printk is not a constant, It means that something not
> > > guaranteed, so the compiler optimizes the fmt out, and then the
> > > __trace_printk_fmt section is not filled. if __trace_printk_fmt is not
> > > filled, the kernel will not allocate the special buffers needed for the
> > > event_trace_printk() and then not shown in the file output
> > > sys/kernel/debug/tracing/print_formats.
> > > 
> > > Adding a "__used" to the variable in the __trace_printk_fmt section on
> > > event_trace_printk() will keep it around, even though it is set to NULL.
> > > This will keep the string from being printed in the
> > > sys/kernel/debug/tracing/printk_formats section.
> > > 
> > > We can also refer to commit 3debb0a9ddb1 ("tracing: Fix trace_printk()
> > > to print when not using bprintk()")that it had similar issue on path of
> > > trace_printk().
> > 
> > Honestly, I don't even remember why that macro was created. I think
> > it's a remnant from the creation of the trace events. I think the best
> > solution is just to nuke it. It shouldn't be used anymore.
> > 
> > I'll dig a bit deeper into the history of that macro, but I'm thinking
> > it shouldn't exist anymore.
> > 
> > [ /me returns from walking down memory lane ]
> > 
> > Wow, that brings back some wild memories. Yes, that macro must die, and
> > I wish the history of it could die along with it ;-) The horror of the
> > old ways I tell you. The event_trace_printk() was the original way we
> > displayed events! No real formatting, no parsing my userspace tools. It
> > was just a glamorized printk. It was called TRACE_FORMAT() which was
> > deprecated by today's TRACE_EVENT().
> > 
> > That macro should have been removed by commit b8e65554d80b4.
> > 
> > Please just send a patch to delete that macro. Let's not be maintaining
> > it. It gives me nightmares.
> > 
> > -- Steve
> 
> Got it, I will send another patch to remove the nightmares. :-)
> 
> Thanks.

After some grep, I found event_trace_printk() not used in 5.0-rc*. But
trace_printk() is still used in several places.

kernel/trace/ring_buffer_benchmark.c:415: trace_printk("Sleeping for 10
secs\n");
...
drivers/gpu/drm/i915/i915_gem.h:66:#define GEM_TRACE(...)
trace_printk(__VA_ARGS__)
drivers/hwtracing/stm/dummy_stm.c:30:   trace_printk("[%u:%u] [pkt: %x/%
x] (%llx)\n", master, channel,
...

since they are similar functions, do you prefer remove both of them or
just remove event_trace_printk()? the former approach might affect some
modules, and the latter approach keeps nightmares, right?

Thanks.
>

Steven Rostedt Feb. 13, 2019, 1:45 p.m. UTC | #4

On Wed, 13 Feb 2019 14:49:45 +0800
Mars Cheng <[e-mail]> wrote:


> After some grep, I found event_trace_printk() not used in 5.0-rc*. But
> trace_printk() is still used in several places.

event_trace_printk() is an abomination, but trace_printk() is an
extremely useful tool. Don't touch that!

-- Steve

Patch

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 8a62731..26bd7c4 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -551,7 +551,7 @@  extern int trace_define_field(struct trace_event_call *call, const char *type,
 	__trace_printk_check_format(fmt, ##args);			\
 	tracing_record_cmdline(current);				\
 	if (__builtin_constant_p(fmt)) {				\
-		static const char *trace_printk_fmt			\
+		static const char *trace_printk_fmt __used		\
 		  __attribute__((section("__trace_printk_fmt"))) =	\
 			__builtin_constant_p(fmt) ? fmt : NULL;		\
 									\