Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers

[Joel Fernandes <agnel.joel@gmail.com>]

Hi Steven,

On Fri, Mar 18, 2016 at 9:44 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> This should fix the issue for you. This probably should be added to
> stable as well (I'll add a tag).

Thanks a lot for working on this.

>
> -- Steve
>
> From e79b49b73079d4320a6ad08eb91d3c92cfef6e6a Mon Sep 17 00:00:00 2001
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> Date: Fri, 18 Mar 2016 12:27:43 -0400
> Subject: [PATCH] tracing: Have preempt(irqs)off trace preempt disabled
>  functions
>
> Joel Fernandes reported that the function tracing of preempt disabled
> sections was not being reported when running either the preemptirqsoff or
> preemptoff tracers. This was due to the fact that the function tracer
> callback for those tracers checked if irqs were disabled before tracing. But
> this fails when we want to trace preempt off locations as well.
>
> Joel explained that he wanted to see funcitons where interrupts are enabled
> but preemption was disabled. The expected output he wanted:
>
>    <...>-2265    1d.h1 3419us : preempt_count_sub <-irq_exit
>    <...>-2265    1d..1 3419us : __do_softirq <-irq_exit
>    <...>-2265    1d..1 3419us : msecs_to_jiffies <-__do_softirq
>    <...>-2265    1d..1 3420us : irqtime_account_irq <-__do_softirq
>    <...>-2265    1d..1 3420us : __local_bh_disable_ip <-__do_softirq
>    <...>-2265    1..s1 3421us : run_timer_softirq <-__do_softirq
>    <...>-2265    1..s1 3421us : hrtimer_run_pending <-run_timer_softirq
>    <...>-2265    1..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq
>    <...>-2265    1d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq
>    <...>-2265    1d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq
>    <...>-2265    1..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq
>    <...>-2265    1..s1 3423us : rcu_bh_qs <-__do_softirq
>    <...>-2265    1d.s1 3423us : irqtime_account_irq <-__do_softirq
>    <...>-2265    1d.s1 3423us : __local_bh_enable <-__do_softirq
>
> There's a comment saying that the irq disabled check is because there's a
> possible race that tracing_cpu may be set when the function is executed. But
> I don't remember that race. For now, I added a check for preemption being
> enabled too to not record the function, as there would be no race if that
> was the case. I need to re-investigate this, as I'm now thinking that the
> tracing_cpu will always be correct. But no harm in keeping the check for
> now, except for the slight performance hit.
>
> Link: http://lkml.kernel.org/r/1457770386-88717-1-git-send-email-agnel.joel@gmail.com
>
> Reported-by: Joel Fernandes <agnel.joel@gmail.com>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  kernel/trace/trace_irqsoff.c | 8 ++++++--
>  1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index e4e56589ec1d..be3222b7d72e 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -109,8 +109,12 @@ static int func_prolog_dec(struct trace_array *tr,
>                 return 0;
>
>         local_save_flags(*flags);
> -       /* slight chance to get a false positive on tracing_cpu */
> -       if (!irqs_disabled_flags(*flags))
> +       /*
> +        * Slight chance to get a false positive on tracing_cpu,
> +        * although I'm starting to think there isn't a chance.
> +        * Leave this for now just to be paranoid.
> +        */
> +       if (!irqs_disabled_flags(*flags) && !preempt_count())
>                 return 0;
>
>         *data = per_cpu_ptr(tr->trace_buffer.data, cpu);
> --

I tested your patch and it fixes the issue for me. I went over some
usecases and I didn't think there was a race with tracing_cpu either.
I would love to take part in any future discussions about this topic
as well.

Thanks again,

Best,
Joel