| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20191003134809.GD254942@google.com>
Date: Thu, 3 Oct 2019 09:48:09 -0400
From: Joel Fernandes <joel@...lfernandes.org>
To: Viktor Rosendahl <viktor.rosendahl@...il.com>
Cc: Steven Rostedt <rostedt@...dmis.org>,
Ingo Molnar <mingo@...hat.com>, linux-kernel@...r.kernel.org
Subject: Re: [PATCH v7 4/4] ftrace: Add an option for tracing console
latencies
On Thu, Oct 03, 2019 at 12:44:09AM +0200, Viktor Rosendahl wrote:
> On 10/2/19 2:52 AM, Joel Fernandes wrote:
> > On Fri, Sep 20, 2019 at 05:22:19PM +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@...il.com>
> > > ---
> > > include/linux/irqflags.h | 22 ++++++++++++++++++++++
> > > kernel/printk/printk.c | 6 ++++--
> > > kernel/trace/trace.h | 1 +
> > > kernel/trace/trace_irqsoff.c | 12 ++++++++++++
> > > 4 files changed, 39 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 1888f6a3b694..036460a7e4cd 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -2359,6 +2359,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) {
> > > @@ -2459,9 +2460,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 4913ed1138aa..93a8b82c27e4 100644
> > > --- a/kernel/trace/trace.h
> > > +++ b/kernel/trace/trace.h
> > > @@ -1262,6 +1262,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..bc02be207a7a 100644
> > > --- a/kernel/trace/trace_irqsoff.c
> > > +++ b/kernel/trace/trace_irqsoff.c
> > > @@ -456,6 +456,18 @@ 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 (!preempt_trace(pc) && !irq_trace())
> > > + return false;
> >
> > Why this condition here? Why not just make the call to
> > stop_critical_timings() dependent on the new flag you are adding? Please
> > explain it more and add some comments.
> >
>
> It is a kind of optimization for the common case, i.e. that the tracer
> is not enabled.
>
> The idea is that if the preemptirqsoff tracing is disabled, then the
> question of whether or not to trace console latencies is moot and by
> telling the caller that it is not disabled, we will prevent the caller
> from making the calls to stop_critical_timings() and
> start_critical_timings(). These calls would only return without doing
> anything if the condition "!preempt_trace(pc) && !irq_trace()" is true,
> since they use the inverse condition "preempt_trace(pc) || irq_trace()"
> to test whether or not they should do anything.
>
> I have to admit that this may be a useless micro optimization that
> makes the code harder to understand and maintain for a benefit that
> is so small that it would be hard to measure.
>
> I feel a bit unsure whether I should try to improve it by adding a
> comment, and perhaps putting the condition into a macro that
> could then also be used by the start/stop_critical_timings() functions,
> or if I should just get rid of the optimization. I guess this console
> code is not a particularly hot code path anyway.
>
> Please let me know what you think.
Oh, I see what you are doing now. I think you can just add a comment on top
of the if block explaining this.
But IIRC the printk code is being rewritten to not have real-time latency
issues, so may be this patch will become obsolete pretty soon?
Unless you really need this patch for your series, I would should just drop it.
thanks,
- Joel
> best regards,
>
> Viktor
>
> > thanks,
> >
> > - Joel
> >
> >
> > > +
> > > + 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
> > >
>
Powered by blists - more mailing lists