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

[Joel Fernandes]

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