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

From: Steven Rostedt
Date: Wed May 01 2019 - 21:39:29 EST


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