Re: [PATCH v8 4/4] ftrace: Add an option for tracing console latencies

[Joel Fernandes <joel@joelfernandes.org>]

On Wed, Oct 09, 2019 at 12:08:24AM +0200, Viktor Rosendahl (BMW) wrote:
> This new trace option "console-latency" will enable the latency
> tracers to trace the console latencies. Previously this has always been
> implicitely disabled. I guess this is because they are considered
> to be well known and unavoidable.
> 
> However, for some organizations it may nevertheless be desirable to
> trace them. Basically, we want to be able to tell that there are
> latencies in the system under test because someone has incorrectly
> enabled the serial console.
> 
> Signed-off-by: Viktor Rosendahl (BMW) <viktor.rosendahl@gmail.com>
> ---
>  include/linux/irqflags.h     | 22 ++++++++++++++++++++++
>  kernel/printk/printk.c       |  6 ++++--
>  kernel/trace/trace.h         |  1 +
>  kernel/trace/trace_irqsoff.c | 18 ++++++++++++++++++
>  4 files changed, 45 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
> index 21619c92c377..3de891723331 100644
> --- a/include/linux/irqflags.h
> +++ b/include/linux/irqflags.h
> @@ -13,6 +13,7 @@
>  #define _LINUX_TRACE_IRQFLAGS_H
>  
>  #include <linux/typecheck.h>
> +#include <linux/types.h>
>  #include <asm/irqflags.h>
>  
>  /* Currently trace_softirqs_on/off is used only by lockdep */
> @@ -68,9 +69,30 @@ do {						\
>  	defined(CONFIG_PREEMPT_TRACER)
>   extern void stop_critical_timings(void);
>   extern void start_critical_timings(void);
> + extern bool console_tracing_disabled(void);
> +
> +# define console_stop_critical_timings(flag)		\
> +	do {						\
> +		typecheck(bool, flag);			\
> +		flag = console_tracing_disabled();	\
> +		if (flag)				\
> +			stop_critical_timings();	\
> +	} while (0)
> +
> +# define console_start_critical_timings(flag)		 \
> +	do {						 \
> +		typecheck(bool, flag);			 \
> +		if (flag)				 \
> +			start_critical_timings();	 \
> +	} while (0)
> +
>  #else
>  # define stop_critical_timings() do { } while (0)
>  # define start_critical_timings() do { } while (0)
> +# define console_stop_critical_timings(flag)	\
> +	do { typecheck(bool, flag); } while (0)
> +# define console_start_critical_timings(flag)	\
> +	do { typecheck(bool, flag); } while (0)
>  #endif
>  
>  /*
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ca65327a6de8..f27e96273453 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2369,6 +2369,7 @@ void console_unlock(void)
>  	static char ext_text[CONSOLE_EXT_LOG_MAX];
>  	static char text[LOG_LINE_MAX + PREFIX_MAX];
>  	unsigned long flags;
> +	bool cflag;
>  	bool do_cond_resched, retry;
>  
>  	if (console_suspended) {
> @@ -2469,9 +2470,10 @@ void console_unlock(void)
>  		 */
>  		console_lock_spinning_enable();
>  
> -		stop_critical_timings();	/* don't trace print latency */
> +		/* don't trace print latency if it's disabled */
> +		console_stop_critical_timings(cflag);
>  		call_console_drivers(ext_text, ext_len, text, len);
> -		start_critical_timings();
> +		console_start_critical_timings(cflag);
>  
>  		if (console_lock_spinning_disable_and_check()) {
>  			printk_safe_exit_irqrestore(flags);
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 591c7a873235..10d12c8f7f77 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1261,6 +1261,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf,
>  		C(PRINTK_MSGONLY,	"printk-msg-only"),	\
>  		C(CONTEXT_INFO,		"context-info"),   /* Print pid/cpu/time */ \
>  		C(LATENCY_FMT,		"latency-format"),	\
> +		C(CONSOLE_LATENCY,	"console-latency"),	\
>  		C(RECORD_CMD,		"record-cmd"),		\
>  		C(RECORD_TGID,		"record-tgid"),		\
>  		C(OVERWRITE,		"overwrite"),		\
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index a745b0cee5d3..576e2162114e 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -456,6 +456,24 @@ void stop_critical_timings(void)
>  EXPORT_SYMBOL_GPL(stop_critical_timings);
>  NOKPROBE_SYMBOL(stop_critical_timings);
>  
> +bool console_tracing_disabled(void)
> +{
> +	struct trace_array *tr = irqsoff_trace;
> +	int pc = preempt_count();
> +
> +	/*
> +	 * If tracing is disabled, then the question of whether to trace console
> +	 * latencies is moot. By always returning false here we save the caller
> +	 * the calls to start/stop_critical_timings(). These calls would not do
> +	 * anything anyway.
> +	 */

I thought you were going to drop this patch, or at least I had suggested so
but did not hear a reply from you: https://lkml.org/lkml/2019/10/3/464

Thanks for adding the comments though.

Steve, what do you think about this patch? I am worried the extra flag may go
obsolete at some point if the console latencies are fixed and we have yet
another knob.

thanks,

 - Joel

> +	if (!preempt_trace(pc) && !irq_trace())
> +		return false;
> +
> +	return !(tr->trace_flags & TRACE_ITER_CONSOLE_LATENCY);
> +}
> +EXPORT_SYMBOL_GPL(console_tracing_disabled);
> +
>  #ifdef CONFIG_FUNCTION_TRACER
>  static bool function_enabled;
>  
> -- 
> 2.17.1
>