tracing: Make sure trace_printk() can output as soon as it can be used

[PATCH] tracing: Make sure trace_printk() can output as soon as it can be used

Posted by Steven Rostedt 2 years, 8 months ago

From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

Currently trace_printk() can be used as soon as early_trace_init() is
called from start_kernel(). But if a crash happens, and
"ftrace_dump_on_oops" is set on the kernel command line, all you get will
be:

  [    0.456075]   <idle>-0         0dN.2. 347519us : Unknown type 6
  [    0.456075]   <idle>-0         0dN.2. 353141us : Unknown type 6
  [    0.456075]   <idle>-0         0dN.2. 358684us : Unknown type 6

This is because the trace_printk() event (type 6) hasn't been registered
yet. That gets done via an early_initcall(), which may be early, but not
early enough.

Instead of registering the trace_printk() event (and other ftrace events,
which are not trace events) via an early_initcall(), have them registered at
the same time that trace_printk() can be used. This way, if there is a
crash before early_initcall(), then the trace_printk()s will actually be
useful.

Cc: stable@vger.kernel.org
Reported-by: "Joel Fernandes (Google)" <joel@joelfernandes.org>
Fixes: e725c731e3bb1 ("tracing: Split tracing initialization into two for early initialization")
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 kernel/trace/trace.c        | 2 ++
 kernel/trace/trace.h        | 1 +
 kernel/trace/trace_output.c | 3 +--
 3 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index d3005279165d..80de338f1277 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -10196,6 +10196,8 @@ void __init early_trace_init(void)
 			static_key_enable(&tracepoint_printk_key.key);
 	}
 	tracer_alloc_buffers();
+
+	init_events();
 }
 
 void __init trace_init(void)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 900e75d96c84..11c4918ff202 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1504,6 +1504,7 @@ extern void trace_event_enable_cmd_record(bool enable);
 extern void trace_event_enable_tgid_record(bool enable);
 
 extern int event_trace_init(void);
+extern int init_events(void);
 extern int event_trace_add_tracer(struct dentry *parent, struct trace_array *tr);
 extern int event_trace_del_tracer(struct trace_array *tr);
 extern void __trace_early_add_events(struct trace_array *tr);
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 67f47ea27921..5cd4fb656306 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1568,7 +1568,7 @@ static struct trace_event *events[] __initdata = {
 	NULL
 };
 
-__init static int init_events(void)
+__init int init_events(void)
 {
 	struct trace_event *event;
 	int i, ret;
@@ -1581,4 +1581,3 @@ __init static int init_events(void)
 
 	return 0;
 }
-early_initcall(init_events);
-- 
2.35.1

Re: [PATCH] tracing: Make sure trace_printk() can output as soon as it can be used

Posted by Joel Fernandes 2 years, 8 months ago

On Wed, Jan 04, 2023 at 04:14:12PM -0500, Steven Rostedt wrote:
> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> Currently trace_printk() can be used as soon as early_trace_init() is
> called from start_kernel(). But if a crash happens, and
> "ftrace_dump_on_oops" is set on the kernel command line, all you get will
> be:
> 
>   [    0.456075]   <idle>-0         0dN.2. 347519us : Unknown type 6
>   [    0.456075]   <idle>-0         0dN.2. 353141us : Unknown type 6
>   [    0.456075]   <idle>-0         0dN.2. 358684us : Unknown type 6
> 
> This is because the trace_printk() event (type 6) hasn't been registered
> yet. That gets done via an early_initcall(), which may be early, but not
> early enough.
> 
> Instead of registering the trace_printk() event (and other ftrace events,
> which are not trace events) via an early_initcall(), have them registered at
> the same time that trace_printk() can be used. This way, if there is a
> crash before early_initcall(), then the trace_printk()s will actually be
> useful.
> 
> Cc: stable@vger.kernel.org
> Reported-by: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> Fixes: e725c731e3bb1 ("tracing: Split tracing initialization into two for early initialization")
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Tested-by: Joel Fernandes (Google) <joel@joelfernandes.org>

thanks,

 - Joel


> ---
>  kernel/trace/trace.c        | 2 ++
>  kernel/trace/trace.h        | 1 +
>  kernel/trace/trace_output.c | 3 +--
>  3 files changed, 4 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index d3005279165d..80de338f1277 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -10196,6 +10196,8 @@ void __init early_trace_init(void)
>  			static_key_enable(&tracepoint_printk_key.key);
>  	}
>  	tracer_alloc_buffers();
> +
> +	init_events();
>  }
>  
>  void __init trace_init(void)
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 900e75d96c84..11c4918ff202 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1504,6 +1504,7 @@ extern void trace_event_enable_cmd_record(bool enable);
>  extern void trace_event_enable_tgid_record(bool enable);
>  
>  extern int event_trace_init(void);
> +extern int init_events(void);
>  extern int event_trace_add_tracer(struct dentry *parent, struct trace_array *tr);
>  extern int event_trace_del_tracer(struct trace_array *tr);
>  extern void __trace_early_add_events(struct trace_array *tr);
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index 67f47ea27921..5cd4fb656306 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -1568,7 +1568,7 @@ static struct trace_event *events[] __initdata = {
>  	NULL
>  };
>  
> -__init static int init_events(void)
> +__init int init_events(void)
>  {
>  	struct trace_event *event;
>  	int i, ret;
> @@ -1581,4 +1581,3 @@ __init static int init_events(void)
>  
>  	return 0;
>  }
> -early_initcall(init_events);
> -- 
> 2.35.1
>