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

[Viktor Rosendahl]

Den ons 9 okt. 2019 kl 16:11 skrev Joel Fernandes <joel@xxxxxxxxxxxxxxxxx>:
>
> 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@xxxxxxxxx>
> > ---
> >  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
>

Apologies, I should have replied there but I have been a bit busy the
last few days with other topics, and I felt a bit indecisive about
that point, so I just sloppily addressed the issue in the cover letter
of this new series:

"I have retained the fourth patch, although it was suggested that is becoming
obsolete soon. I have retained it only because I do not know the status of
the code that will make it obsolete. It's the last patch of the series and
if there indeed is some code that will remove the latency issues from the
printk code, then of course it makes sense to drop it. The first three patches
will work without it."

I thought that, since it's the last in the series, it would be
possible for maintainers to just take the first three if the last one
is not wanted.

For me it solves a rather important problem though, so if the code
that will make it obsolete isn't available for some time, then perhaps
it should be considered as a temporary solution.

Of course, if there is a commitment to never remove any knobs from
/sys/kernel/debug/tracing/trace_options, then I can easily understand
that it's not wanted as a temporary fix.

best regards,

Viktor

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