Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932907AbcCTB57 (ORCPT ); Sat, 19 Mar 2016 21:57:59 -0400 Received: from mail-lb0-f180.google.com ([209.85.217.180]:34550 "EHLO mail-lb0-f180.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932619AbcCTB56 (ORCPT ); Sat, 19 Mar 2016 21:57:58 -0400 MIME-Version: 1.0 In-Reply-To: <20160318124448.1e20bf67@gandalf.local.home> References: <1457770386-88717-1-git-send-email-agnel.joel@gmail.com> <20160318111332.69e79e38@gandalf.local.home> <20160318124448.1e20bf67@gandalf.local.home> Date: Sat, 19 Mar 2016 18:57:56 -0700 Message-ID: Subject: Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers From: Joel Fernandes To: Steven Rostedt Cc: Linux Kernel Mailing List , Ingo Molnar Content-Type: text/plain; charset=UTF-8 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 3839 Lines: 87 Hi Steven, On Fri, Mar 18, 2016 at 9:44 AM, Steven Rostedt 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)" > 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 > Signed-off-by: Steven Rostedt > --- > 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