Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
Hi Steven, On Fri, Mar 18, 2016 at 9:44 AM, Steven Rostedtwrote: > 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: > ><...>-22651d.h1 3419us : preempt_count_sub <-irq_exit ><...>-22651d..1 3419us : __do_softirq <-irq_exit ><...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq ><...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq ><...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq ><...>-22651..s1 3421us : run_timer_softirq <-__do_softirq ><...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq ><...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq ><...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq ><...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq ><...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq ><...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq ><...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq ><...>-22651d.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.j...@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
Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
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: > ><...>-22651d.h1 3419us : preempt_count_sub <-irq_exit ><...>-22651d..1 3419us : __do_softirq <-irq_exit ><...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq ><...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq ><...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq ><...>-22651..s1 3421us : run_timer_softirq <-__do_softirq ><...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq ><...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq ><...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq ><...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq ><...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq ><...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq ><...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq ><...>-22651d.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.j...@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
Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
On Sat, 12 Mar 2016 00:13:06 -0800 Joel Fernandeswrote: > All functions aren't traced in critical sections where preemption is disabled > and interrupts are enabled in preempt* tracers because current behavior is to > check if interrupts are disabled and if they are not, then we don't trace > these > functions. So here we do the correct checks depending on tracer type and allow > these functions to be traced. > > One example is when interrupts are enabled before softirq processing, with the > patch, these functions are traced as well. > ><...>-22651d.h1 3419us : preempt_count_sub <-irq_exit ><...>-22651d..1 3419us : __do_softirq <-irq_exit ><...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq ><...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq ><...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq ><...>-22651..s1 3421us : run_timer_softirq <-__do_softirq ><...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq ><...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq ><...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq ><...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq ><...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq ><...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq ><...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq ><...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq > > Cc: Steven Rostedt > Cc: Ingo Molnar > Signed-off-by: Joel Fernandes > --- > kernel/trace/trace_irqsoff.c | 16 ++-- > 1 file changed, 14 insertions(+), 2 deletions(-) > > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c > index e4e5658..ca8f84f 100644 > --- a/kernel/trace/trace_irqsoff.c > +++ b/kernel/trace/trace_irqsoff.c > @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, > > local_save_flags(*flags); > /* slight chance to get a false positive on tracing_cpu */ > - if (!irqs_disabled_flags(*flags)) > - return 0; > + switch (trace_type) { > + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): > + if (!preempt_trace() && !irqs_disabled_flags(*flags)) > + return 0; > + break; > + case TRACER_IRQS_OFF: > + if (!irqs_disabled_flags(*flags)) > + return 0; > + break; > + case TRACER_PREEMPT_OFF: > + if (!preempt_trace()) > + return 0; > + break; > + } Actually this is too complex a fix. If tracing_cpu is set, we want to trace this cpu. And I'm starting to think we don't even need this check, because I'm having a hard time seeing how tracing_cpu could be set without preemption or irqs being disabled, and thus there be no race. Anyway, we can just add a check if either irqs are disabled or interrupts are disabled: if (!irqs_disabled_flags(*flags) && !preempt_count()) return 0; -- Steve > > *data = per_cpu_ptr(tr->trace_buffer.data, cpu); > disabled = atomic_inc_return(&(*data)->disabled);
Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
On Sat, 12 Mar 2016 00:13:06 -0800 Joel Fernandes wrote: > All functions aren't traced in critical sections where preemption is disabled > and interrupts are enabled in preempt* tracers because current behavior is to > check if interrupts are disabled and if they are not, then we don't trace > these > functions. So here we do the correct checks depending on tracer type and allow > these functions to be traced. > > One example is when interrupts are enabled before softirq processing, with the > patch, these functions are traced as well. > ><...>-22651d.h1 3419us : preempt_count_sub <-irq_exit ><...>-22651d..1 3419us : __do_softirq <-irq_exit ><...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq ><...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq ><...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq ><...>-22651..s1 3421us : run_timer_softirq <-__do_softirq ><...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq ><...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq ><...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq ><...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq ><...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq ><...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq ><...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq ><...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq > > Cc: Steven Rostedt > Cc: Ingo Molnar > Signed-off-by: Joel Fernandes > --- > kernel/trace/trace_irqsoff.c | 16 ++-- > 1 file changed, 14 insertions(+), 2 deletions(-) > > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c > index e4e5658..ca8f84f 100644 > --- a/kernel/trace/trace_irqsoff.c > +++ b/kernel/trace/trace_irqsoff.c > @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, > > local_save_flags(*flags); > /* slight chance to get a false positive on tracing_cpu */ > - if (!irqs_disabled_flags(*flags)) > - return 0; > + switch (trace_type) { > + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): > + if (!preempt_trace() && !irqs_disabled_flags(*flags)) > + return 0; > + break; > + case TRACER_IRQS_OFF: > + if (!irqs_disabled_flags(*flags)) > + return 0; > + break; > + case TRACER_PREEMPT_OFF: > + if (!preempt_trace()) > + return 0; > + break; > + } Actually this is too complex a fix. If tracing_cpu is set, we want to trace this cpu. And I'm starting to think we don't even need this check, because I'm having a hard time seeing how tracing_cpu could be set without preemption or irqs being disabled, and thus there be no race. Anyway, we can just add a check if either irqs are disabled or interrupts are disabled: if (!irqs_disabled_flags(*flags) && !preempt_count()) return 0; -- Steve > > *data = per_cpu_ptr(tr->trace_buffer.data, cpu); > disabled = atomic_inc_return(&(*data)->disabled);
Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
This should fix the issue for you. This probably should be added to stable as well (I'll add a tag). -- 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: <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.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.j...@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); -- 1.8.3.1
Re: [PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
This should fix the issue for you. This probably should be added to stable as well (I'll add a tag). -- 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: <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.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.j...@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); -- 1.8.3.1
[PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
All functions aren't traced in critical sections where preemption is disabled and interrupts are enabled in preempt* tracers because current behavior is to check if interrupts are disabled and if they are not, then we don't trace these functions. So here we do the correct checks depending on tracer type and allow these functions to be traced. One example is when interrupts are enabled before softirq processing, with the patch, these functions are traced as well. <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq Cc: Steven RostedtCc: Ingo Molnar Signed-off-by: Joel Fernandes --- kernel/trace/trace_irqsoff.c | 16 ++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index e4e5658..ca8f84f 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, local_save_flags(*flags); /* slight chance to get a false positive on tracing_cpu */ - if (!irqs_disabled_flags(*flags)) - return 0; + switch (trace_type) { + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): + if (!preempt_trace() && !irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_IRQS_OFF: + if (!irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_PREEMPT_OFF: + if (!preempt_trace()) + return 0; + break; + } *data = per_cpu_ptr(tr->trace_buffer.data, cpu); disabled = atomic_inc_return(&(*data)->disabled); -- 2.5.0
[PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
All functions aren't traced in critical sections where preemption is disabled and interrupts are enabled in preempt* tracers because current behavior is to check if interrupts are disabled and if they are not, then we don't trace these functions. So here we do the correct checks depending on tracer type and allow these functions to be traced. One example is when interrupts are enabled before softirq processing, with the patch, these functions are traced as well. <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq Cc: Steven Rostedt Cc: Ingo Molnar Signed-off-by: Joel Fernandes --- kernel/trace/trace_irqsoff.c | 16 ++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index e4e5658..ca8f84f 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, local_save_flags(*flags); /* slight chance to get a false positive on tracing_cpu */ - if (!irqs_disabled_flags(*flags)) - return 0; + switch (trace_type) { + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): + if (!preempt_trace() && !irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_IRQS_OFF: + if (!irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_PREEMPT_OFF: + if (!preempt_trace()) + return 0; + break; + } *data = per_cpu_ptr(tr->trace_buffer.data, cpu); disabled = atomic_inc_return(&(*data)->disabled); -- 2.5.0
[PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
All functions aren't traced in critical sections where preemption is disabled and interrupts are enabled in preempt* tracers because current behavior is to check if interrupts are disabled and if they are not, then we don't trace these functions. So here we do the correct checks depending on tracer type and allow these functions to be traced. One example is when interrupts are enabled before softirq processing, with the patch, these functions are traced as well. <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq Signed-off-by: Joel Fernandes--- kernel/trace/trace_irqsoff.c | 16 ++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index e4e5658..ca8f84f 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, local_save_flags(*flags); /* slight chance to get a false positive on tracing_cpu */ - if (!irqs_disabled_flags(*flags)) - return 0; + switch (trace_type) { + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): + if (!preempt_trace() && !irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_IRQS_OFF: + if (!irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_PREEMPT_OFF: + if (!preempt_trace()) + return 0; + break; + } *data = per_cpu_ptr(tr->trace_buffer.data, cpu); disabled = atomic_inc_return(&(*data)->disabled); -- 2.5.0
[PATCH] trace: irqsoff: Fix function tracing in preempt and preemptirqsoff tracers
All functions aren't traced in critical sections where preemption is disabled and interrupts are enabled in preempt* tracers because current behavior is to check if interrupts are disabled and if they are not, then we don't trace these functions. So here we do the correct checks depending on tracer type and allow these functions to be traced. One example is when interrupts are enabled before softirq processing, with the patch, these functions are traced as well. <...>-22651d.h1 3419us : preempt_count_sub <-irq_exit <...>-22651d..1 3419us : __do_softirq <-irq_exit <...>-22651d..1 3419us : msecs_to_jiffies <-__do_softirq <...>-22651d..1 3420us : irqtime_account_irq <-__do_softirq <...>-22651d..1 3420us : __local_bh_disable_ip <-__do_softirq <...>-22651..s1 3421us : run_timer_softirq <-__do_softirq <...>-22651..s1 3421us : hrtimer_run_pending <-run_timer_softirq <...>-22651..s1 3421us : _raw_spin_lock_irq <-run_timer_softirq <...>-22651d.s1 3422us : preempt_count_add <-_raw_spin_lock_irq <...>-22651d.s2 3422us : _raw_spin_unlock_irq <-run_timer_softirq <...>-22651..s2 3422us : preempt_count_sub <-_raw_spin_unlock_irq <...>-22651..s1 3423us : rcu_bh_qs <-__do_softirq <...>-22651d.s1 3423us : irqtime_account_irq <-__do_softirq <...>-22651d.s1 3423us : __local_bh_enable <-__do_softirq Signed-off-by: Joel Fernandes --- kernel/trace/trace_irqsoff.c | 16 ++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index e4e5658..ca8f84f 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -110,8 +110,20 @@ static int func_prolog_dec(struct trace_array *tr, local_save_flags(*flags); /* slight chance to get a false positive on tracing_cpu */ - if (!irqs_disabled_flags(*flags)) - return 0; + switch (trace_type) { + case (TRACER_IRQS_OFF | TRACER_PREEMPT_OFF): + if (!preempt_trace() && !irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_IRQS_OFF: + if (!irqs_disabled_flags(*flags)) + return 0; + break; + case TRACER_PREEMPT_OFF: + if (!preempt_trace()) + return 0; + break; + } *data = per_cpu_ptr(tr->trace_buffer.data, cpu); disabled = atomic_inc_return(&(*data)->disabled); -- 2.5.0