Re: [PATCH v6 2/2] tracing: Add support for preempt and irq enable/disable events

From: Peter Zijlstra
Date: Fri Sep 22 2017 - 05:02:39 EST


On Thu, Sep 21, 2017 at 06:50:24PM -0700, Joel Fernandes wrote:
> +DECLARE_EVENT_CLASS(preemptirq_template,
> +
> + TP_PROTO(unsigned long ip, unsigned long parent_ip),
> +
> + TP_ARGS(ip, parent_ip),
> +
> + TP_STRUCT__entry(
> + __field(u32, caller_offs)
> + __field(u32, parent_offs)
> + ),
> +
> + TP_fast_assign(
> + __entry->caller_offs = (u32)(ip - (unsigned long)_stext);
> + __entry->parent_offs = (u32)(parent_ip - (unsigned long)_stext);
> + ),
> +
> + TP_printk("caller=%pF parent=%pF",
> + (void *)((unsigned long)(_stext) + __entry->caller_offs),
> + (void *)((unsigned long)(_stext) + __entry->parent_offs))
> +);

So I don't get that function prototype. Why do we need two IPs?

> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 26c688740742..f3087e7278cb 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -16,6 +16,9 @@
>
> #include "trace.h"
>
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/preemptirq.h>
> +
> #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
> static struct trace_array *irqsoff_trace __read_mostly;
> static int tracer_enabled __read_mostly;
> @@ -777,14 +780,29 @@ static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
> static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
> #endif
>
> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
> +static DEFINE_PER_CPU(int, tracing_preempt_cpu);
> +
> void start_critical_timings(void)
> {
> + if (this_cpu_read(tracing_preempt_cpu))
> + trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> +
> + if (this_cpu_read(tracing_irq_cpu))
> + trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> +
> start_critical_timings_tracer();
> }
> EXPORT_SYMBOL_GPL(start_critical_timings);
>
> void stop_critical_timings(void)
> {
> + if (this_cpu_read(tracing_preempt_cpu))
> + trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> +
> + if (this_cpu_read(tracing_irq_cpu))
> + trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> +
> stop_critical_timings_tracer();
> }
> EXPORT_SYMBOL_GPL(stop_critical_timings);

And I feel these yield somewhat odd semantics, does that need explaining
somewhere?

> @@ -792,24 +810,48 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
> #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
> void trace_hardirqs_on(void)
> {
> + if (!this_cpu_read(tracing_irq_cpu))
> + return;
> +
> + trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> tracer_hardirqs_on();
> +
> + this_cpu_write(tracing_irq_cpu, 0);
> }
> EXPORT_SYMBOL(trace_hardirqs_on);
>
> void trace_hardirqs_off(void)
> {
> + if (this_cpu_read(tracing_irq_cpu))
> + return;
> +
> + this_cpu_write(tracing_irq_cpu, 1);
> +
> + trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
> tracer_hardirqs_off();
> }
> EXPORT_SYMBOL(trace_hardirqs_off);
>
> __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
> {
> + if (!this_cpu_read(tracing_irq_cpu))
> + return;
> +
> + trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
> tracer_hardirqs_on_caller(caller_addr);
> +
> + this_cpu_write(tracing_irq_cpu, 0);
> }
> EXPORT_SYMBOL(trace_hardirqs_on_caller);
>
> __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
> {
> + if (this_cpu_read(tracing_irq_cpu))
> + return;
> +
> + this_cpu_write(tracing_irq_cpu, 1);
> +
> + trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
> tracer_hardirqs_off_caller(caller_addr);
> }
> EXPORT_SYMBOL(trace_hardirqs_off_caller);
> @@ -831,14 +873,27 @@ inline void print_irqtrace_events(struct task_struct *curr)
> }
> #endif
>
> -#ifdef CONFIG_PREEMPT_TRACER
> +#if defined(CONFIG_PREEMPT_TRACER) || \
> + (defined(CONFIG_DEBUG_PREEMPT) && defined(CONFIG_PREEMPTIRQ_EVENTS))
> void trace_preempt_on(unsigned long a0, unsigned long a1)
> {
> + if (!this_cpu_read(tracing_preempt_cpu))
> + return;
> +
> + trace_preempt_enable_rcuidle(a0, a1);
> tracer_preempt_on(a0, a1);
> +
> + this_cpu_write(tracing_preempt_cpu, 0);
> }
>
> void trace_preempt_off(unsigned long a0, unsigned long a1)
> {
> + if (this_cpu_read(tracing_preempt_cpu))
> + return;
> +
> + this_cpu_write(tracing_preempt_cpu, 1);
> +
> + trace_preempt_disable_rcuidle(a0, a1);
> tracer_preempt_off(a0, a1);
> }
> #endif

And here you assume things like double on / double off don't happen,
which might well be so, but does seem somewhat fragile.


So all in all I don't see anything particularly wrong, but I see lots
that could do with explaining.