Messages in this thread | | | Date | Sat, 19 Mar 2016 18:57:56 -0700 | Subject | Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers | From | Joel Fernandes <> |
| |
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
| |