| Message ID | 20230613095537.0ecf2459@gandalf.local.home (mailing list archive) |
|---|---|
| State | New, archived |
| Delegated to: | Masami Hiramatsu |
| Headers | show |
| Series | [v2] tracing: Add a debug_trace_printk() function | expand |
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 >
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
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();