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

[Steven Rostedt]

On Wed,  1 May 2019 22:36:50 +0200
Viktor Rosendahl <viktor.rosendahl@xxxxxxxxx> wrote:

> This new option CONFIG_TRACE_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.
> 

I'd rather have this be a tracing option than a config one.

> Signed-off-by: Viktor Rosendahl <viktor.rosendahl@xxxxxxxxx>
> ---
>  include/linux/irqflags.h | 13 +++++++++++++
>  kernel/printk/printk.c   |  5 +++--
>  kernel/trace/Kconfig     | 11 +++++++++++
>  3 files changed, 27 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
> index 21619c92c377..791bee718448 100644
> --- a/include/linux/irqflags.h
> +++ b/include/linux/irqflags.h
> @@ -73,6 +73,19 @@ do {						\
>  # define start_critical_timings() do { } while (0)
>  #endif
>  
> +#ifdef CONFIG_TRACE_CONSOLE_LATENCY
> +
> +#define console_stop_critical_timings()  do {} while (0)
> +#define console_start_critical_timings() do {} while (0)
> +
> +#else /* !CONFIG_TRACE_CONSOLE_LATENCY */
> +
> +/* don't trace print latency */
> +#define console_stop_critical_timings()  stop_critical_timings()
> +#define console_start_critical_timings() start_critical_timings()

Instead of this being turned into a nop, don't have a kconfig option
but instead have this call into the trace_irqsoff.c code, and depending
on what the options are, it should stop it. Of course, this would need
to be smart enough to pair it. Perhaps return the result of
console_stop_critical_timings() and have that passed to
console_start_critical_timings(), and only have start do something if
stop did something. This way the option only needs to disable the stop
part.

-- Steve

> +
> +#endif /* !CONFIG_TRACE_CONSOLE_LATENCY */
> +
>  /*
>   * Wrap the arch provided IRQ routines to provide appropriate checks.
>   */
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 02ca827b8fac..710e87f61158 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2448,9 +2448,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();
>  		call_console_drivers(ext_text, ext_len, text, len);
> -		start_critical_timings();
> +		console_start_critical_timings();
>  
>  		if (console_lock_spinning_disable_and_check()) {
>  			printk_safe_exit_irqrestore(flags);
> diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
> index e5e8f2a0199e..f168d100d4fb 100644
> --- a/kernel/trace/Kconfig
> +++ b/kernel/trace/Kconfig
> @@ -244,6 +244,17 @@ config PREEMPT_TRACER
>  	  modification of /sys/kernel/debug/tracing/trace through
> the inotify interface.
>  
> +	config TRACE_CONSOLE_LATENCY
> +	bool "Do not turn off latency tracing for the console"
> +	default n
> +	depends on IRQSOFF_TRACER || PREEMPT_TRACER
> +	help
> +	  Some of the console drivers will cause long unavoidable
> +	  latencies because they are slow and need to print
> immediately
> +	  in a serialized manner. Because of this their latencies
> are not
> +	  traced by default. This option will change behavior so that
> +	  they are traced.
> +
>  config SCHED_TRACER
>  	bool "Scheduling Latency Tracer"
>  	select GENERIC_TRACER