[PATCH v2] tracing: Add a debug_trace_printk() function

[PATCH v2] tracing: Add a debug_trace_printk() function

[Steven Rostedt]

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

While doing some tracing and kernel debugging, I found that some of my
trace_printk()s were being lost in the noise of the other code that was
being traced. Having a way to write trace_printk() not in the top level
trace buffer would have been useful.

There was also a time I needed to debug ftrace itself, where
trace_printk() did not hit the paths that were being debugged. But because
the trace that was being debugged, was going into the top level ring
buffer, it was causing issues for seeing what is to be traced.

To solve both of the above, add a debug_trace_printk() that can be used
just like trace_printk() except that it goes into a "debug" instance
buffer instead. This can be used at boot up as well.

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Changes since v1: https://lore.kernel.org/linux-trace-kernel/20230612193337.0fb0d3ca@gandalf.local.home/

  - I had added a prompt to the kconfig but never committed it.
    It's now part of the patch.

 include/linux/kernel.h | 14 ++++++++++++++
 kernel/trace/Kconfig   | 20 ++++++++++++++++++++
 kernel/trace/trace.c   | 29 +++++++++++++++++++++++++++++
 3 files changed, 63 insertions(+)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 0d91e0af0125..594c9ba17fd4 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -432,6 +432,20 @@ __ftrace_vbprintk(unsigned long ip, const char *fmt, va_list ap);
 extern __printf(2, 0) int
 __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap);
 
+#ifdef CONFIG_FTRACE_DEBUG_PRINT
+extern __printf(2,0) void do_debug_trace_printk(unsigned long ip, const char *fmt, ...);
+#define debug_trace_printk(fmt, ...) \
+do {							\
+	do_debug_trace_printk(_THIS_IP_, fmt, ##__VA_ARGS__);	\
+} while (0)
+
+extern void debug_tracing_stop(void);
+#else
+#define debug_trace_printk(fmt, ...) do { } while (0)
+static inline void debug_tracing_stop(void) { }
+#endif
+
+
 extern void ftrace_dump(enum ftrace_dump_mode oops_dump_mode);
 #else
 static inline void tracing_start(void) { }
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index abe5c583bd59..e07bca39dec9 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -974,6 +974,26 @@ config GCOV_PROFILE_FTRACE
 	  Note that on a kernel compiled with this config, ftrace will
 	  run significantly slower.
 
+config FTRACE_DEBUG_PRINT
+	bool "Enable debug_trace_printk()"
+	depends on TRACING
+	help
+	  This option enables the use of debug_trace_printk() instead of
+	  using trace_printk(). The difference between the two is that
+	  debug_trace_printk() traces are visible in the "debug" instance
+	  found in:
+
+	  /sys/kernel/tracing/instances/debug
+
+	  This is useful when the trace printks should not interfere with
+	  the normal top level tracing. It is also useful if the top level
+	  tracing is very noisy and critical trace printks are dropped.
+	  By using debug_trace_printk() the traces goes into as separate
+	  ring buffer that will not be overridden by other trace events.
+
+	  If unsure say N (In fact, only say Y if you are debugging a
+	                   kernel and require this)
+
 config FTRACE_SELFTEST
 	bool
 
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 64a4dde073ef..c21a93cf5fd8 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -490,6 +490,10 @@ static struct trace_array global_trace = {
 	.trace_flags = TRACE_DEFAULT_FLAGS,
 };
 
+#ifdef CONFIG_FTRACE_DEBUG_PRINT
+static struct trace_array *debug_trace;
+#endif
+
 LIST_HEAD(ftrace_trace_arrays);
 
 int trace_array_get(struct trace_array *this_tr)
@@ -10455,8 +10459,33 @@ void __init early_trace_init(void)
 	tracer_alloc_buffers();
 
 	init_events();
+
+#ifdef CONFIG_FTRACE_DEBUG_PRINT
+	debug_trace = trace_array_get_by_name("debug");
+	if (WARN_ON(!debug_trace))
+		return;
+	trace_array_init_printk(debug_trace);
+#endif
 }
 
+#ifdef CONFIG_FTRACE_DEBUG_PRINT
+__printf(2, 0)
+void do_debug_trace_printk(unsigned long ip, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	trace_array_vprintk(debug_trace, ip, fmt, ap);
+	va_end(ap);
+}
+
+void debug_tracing_stop(void)
+{
+	debug_trace_printk("Stopping debug tracing\n");
+	tracing_stop_tr(debug_trace);
+}
+#endif
+
 void __init trace_init(void)
 {
 	trace_event_init();
-- 
2.39.2

Re: [PATCH v2] tracing: Add a debug_trace_printk() function

[Masami Hiramatsu]

On Tue, 13 Jun 2023 09:55:37 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> While doing some tracing and kernel debugging, I found that some of my
> trace_printk()s were being lost in the noise of the other code that was
> being traced. Having a way to write trace_printk() not in the top level
> trace buffer would have been useful.
> 
> There was also a time I needed to debug ftrace itself, where
> trace_printk() did not hit the paths that were being debugged. But because
> the trace that was being debugged, was going into the top level ring
> buffer, it was causing issues for seeing what is to be traced.
> 
> To solve both of the above, add a debug_trace_printk() that can be used
> just like trace_printk() except that it goes into a "debug" instance
> buffer instead. This can be used at boot up as well.
> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Sorry, I missed this patch.
As far as it depends CONFIG_FTRACE_DEBUG_PRINT, this looks good to me.

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

BTW, what about adding generic trace_loglvl_printk(loglvl, fmt, ...)?

This is a macro that will be expanded to 'trace_loglvl_<N>_printk(fmt, ...)'
where N is 0-9. Then we can filter the trace_loglvl_N_printk event to a
specific instance.

Thank you,

> ---
> Changes since v1: https://lore.kernel.org/linux-trace-kernel/20230612193337.0fb0d3ca@gandalf.local.home/
> 
>   - I had added a prompt to the kconfig but never committed it.
>     It's now part of the patch.
> 
>  include/linux/kernel.h | 14 ++++++++++++++
>  kernel/trace/Kconfig   | 20 ++++++++++++++++++++
>  kernel/trace/trace.c   | 29 +++++++++++++++++++++++++++++
>  3 files changed, 63 insertions(+)
> 
> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> index 0d91e0af0125..594c9ba17fd4 100644
> --- a/include/linux/kernel.h
> +++ b/include/linux/kernel.h
> @@ -432,6 +432,20 @@ __ftrace_vbprintk(unsigned long ip, const char *fmt, va_list ap);
>  extern __printf(2, 0) int
>  __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap);
>  
> +#ifdef CONFIG_FTRACE_DEBUG_PRINT
> +extern __printf(2,0) void do_debug_trace_printk(unsigned long ip, const char *fmt, ...);
> +#define debug_trace_printk(fmt, ...) \
> +do {							\
> +	do_debug_trace_printk(_THIS_IP_, fmt, ##__VA_ARGS__);	\
> +} while (0)
> +
> +extern void debug_tracing_stop(void);
> +#else
> +#define debug_trace_printk(fmt, ...) do { } while (0)
> +static inline void debug_tracing_stop(void) { }
> +#endif
> +
> +
>  extern void ftrace_dump(enum ftrace_dump_mode oops_dump_mode);
>  #else
>  static inline void tracing_start(void) { }
> diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
> index abe5c583bd59..e07bca39dec9 100644
> --- a/kernel/trace/Kconfig
> +++ b/kernel/trace/Kconfig
> @@ -974,6 +974,26 @@ config GCOV_PROFILE_FTRACE
>  	  Note that on a kernel compiled with this config, ftrace will
>  	  run significantly slower.
>  
> +config FTRACE_DEBUG_PRINT
> +	bool "Enable debug_trace_printk()"
> +	depends on TRACING
> +	help
> +	  This option enables the use of debug_trace_printk() instead of
> +	  using trace_printk(). The difference between the two is that
> +	  debug_trace_printk() traces are visible in the "debug" instance
> +	  found in:
> +
> +	  /sys/kernel/tracing/instances/debug
> +
> +	  This is useful when the trace printks should not interfere with
> +	  the normal top level tracing. It is also useful if the top level
> +	  tracing is very noisy and critical trace printks are dropped.
> +	  By using debug_trace_printk() the traces goes into as separate
> +	  ring buffer that will not be overridden by other trace events.
> +
> +	  If unsure say N (In fact, only say Y if you are debugging a
> +	                   kernel and require this)
> +
>  config FTRACE_SELFTEST
>  	bool
>  
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 64a4dde073ef..c21a93cf5fd8 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -490,6 +490,10 @@ static struct trace_array global_trace = {
>  	.trace_flags = TRACE_DEFAULT_FLAGS,
>  };
>  
> +#ifdef CONFIG_FTRACE_DEBUG_PRINT
> +static struct trace_array *debug_trace;
> +#endif
> +
>  LIST_HEAD(ftrace_trace_arrays);
>  
>  int trace_array_get(struct trace_array *this_tr)
> @@ -10455,8 +10459,33 @@ void __init early_trace_init(void)
>  	tracer_alloc_buffers();
>  
>  	init_events();
> +
> +#ifdef CONFIG_FTRACE_DEBUG_PRINT
> +	debug_trace = trace_array_get_by_name("debug");
> +	if (WARN_ON(!debug_trace))
> +		return;
> +	trace_array_init_printk(debug_trace);
> +#endif
>  }
>  
> +#ifdef CONFIG_FTRACE_DEBUG_PRINT
> +__printf(2, 0)
> +void do_debug_trace_printk(unsigned long ip, const char *fmt, ...)
> +{
> +	va_list ap;
> +
> +	va_start(ap, fmt);
> +	trace_array_vprintk(debug_trace, ip, fmt, ap);
> +	va_end(ap);
> +}
> +
> +void debug_tracing_stop(void)
> +{
> +	debug_trace_printk("Stopping debug tracing\n");
> +	tracing_stop_tr(debug_trace);
> +}
> +#endif
> +
>  void __init trace_init(void)
>  {
>  	trace_event_init();
> -- 
> 2.39.2
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v2] tracing: Add a debug_trace_printk() function

[Steven Rostedt]

On Sun, 30 Jul 2023 10:43:21 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> Sorry, I missed this patch.
> As far as it depends CONFIG_FTRACE_DEBUG_PRINT, this looks good to me.
> 
> Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Thanks, note I've been holding off on applying it to make sure I really do
need it. I have used it twice since posting. It's great to debug something
in the tracing infrastructure ;-)

> 
> BTW, what about adding generic trace_loglvl_printk(loglvl, fmt, ...)?
> 
> This is a macro that will be expanded to 'trace_loglvl_<N>_printk(fmt, ...)'
> where N is 0-9. Then we can filter the trace_loglvl_N_printk event to a
> specific instance.

Hmm, interesting idea. I'll have to think about it.

-- Steve