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

[Google]

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

> From: "Steven Rostedt (Google)" <rostedt@xxxxxxxxxxx>
> 
> 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@xxxxxxxxxxx>

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@xxxxxxxxxx>

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@xxxxxxxxxxxxxxxxxx/
> 
>   - 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@xxxxxxxxxx>