Recently we tried to make the preemptirqsoff tracer to use irqsoff
tracepoint probes. However this causes issues as reported by Masami:
[2.271078] Testing tracer preemptirqsoff: .. no entries found ..FAILED!
[2.381015] WARNING: CPU: 0 PID: 1 at /home/mhiramat/ksrc/linux/kernel/
trace/trace.c:1512 run_tracer_selftest+0xf3/0x154
This is due to the tracepoint code increasing the preempt nesting count
by calling an additional preempt_disable before calling into the
preemptoff tracer which messes up the preempt_count() check in
tracer_hardirqs_off.
To fix this, make the irqsoff tracer probes balance the additional outer
preempt_disable with a preempt_enable_notrace.
The other way to fix this is to just use SRCU for all tracepoints.
However we can't do that because we can't use NMIs from RCU context.
Fixes: c3bc8fd637a9 ("tracing: Centralize preemptirq tracepoints
and unify their usage")
Fixes: e6753f23d961 ("tracepoint: Make rcuidle tracepoint callers use SRCU")
Reported-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Joel Fernandes (Google) <[email protected]>
---
kernel/trace/trace_irqsoff.c | 26 ++++++++++++++++++++++++++
1 file changed, 26 insertions(+)
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 770cd30cda40..ffbf1505d5bc 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -603,14 +603,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
*/
static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
{
+ /*
+ * Tracepoint probes are expected to be called with preempt disabled,
+ * We don't care about being called with preempt disabled but we need
+ * to know in the future if that changes so we can remove the next
+ * preempt_enable.
+ */
+ WARN_ON_ONCE(!preempt_count());
+
+ /* Tracepoint probes disable preemption atleast once, account for that */
+ preempt_enable_notrace();
+
if (!preempt_trace() && irq_trace())
stop_critical_timing(a0, a1);
+
+ preempt_disable_notrace();
}
static void tracer_hardirqs_off(void *none, unsigned long a0, unsigned long a1)
{
+ /*
+ * Tracepoint probes are expected to be called with preempt disabled,
+ * We don't care about being called with preempt disabled but we need
+ * to know in the future if that changes so we can remove the next
+ * preempt_enable.
+ */
+ WARN_ON_ONCE(!preempt_count());
+
+ /* Tracepoint probes disable preemption atleast once, account for that */
+ preempt_enable_notrace();
+
if (!preempt_trace() && irq_trace())
start_critical_timing(a0, a1);
+
+ preempt_disable_notrace();
}
static int irqsoff_tracer_init(struct trace_array *tr)
--
2.18.0.597.ga71716f1ad-goog
On Sun, 5 Aug 2018 20:40:49 -0700
"Joel Fernandes (Google)" <[email protected]> wrote:
> Recently we tried to make the preemptirqsoff tracer to use irqsoff
> tracepoint probes. However this causes issues as reported by Masami:
>
> [2.271078] Testing tracer preemptirqsoff: .. no entries found ..FAILED!
> [2.381015] WARNING: CPU: 0 PID: 1 at /home/mhiramat/ksrc/linux/kernel/
> trace/trace.c:1512 run_tracer_selftest+0xf3/0x154
>
> This is due to the tracepoint code increasing the preempt nesting count
> by calling an additional preempt_disable before calling into the
> preemptoff tracer which messes up the preempt_count() check in
> tracer_hardirqs_off.
>
> To fix this, make the irqsoff tracer probes balance the additional outer
> preempt_disable with a preempt_enable_notrace.
I've tested it and ensured this fixes the problem.
Tested-by: Masami Hiramatsu <[email protected]>
And I have a comment on this code.
>
> The other way to fix this is to just use SRCU for all tracepoints.
> However we can't do that because we can't use NMIs from RCU context.
>
> Fixes: c3bc8fd637a9 ("tracing: Centralize preemptirq tracepoints
> and unify their usage")
> Fixes: e6753f23d961 ("tracepoint: Make rcuidle tracepoint callers use SRCU")
> Reported-by: Masami Hiramatsu <[email protected]>
> Signed-off-by: Joel Fernandes (Google) <[email protected]>
> ---
> kernel/trace/trace_irqsoff.c | 26 ++++++++++++++++++++++++++
> 1 file changed, 26 insertions(+)
>
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 770cd30cda40..ffbf1505d5bc 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -603,14 +603,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
> */
> static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
> {
To ensure this function must not be preempted even if we increment preempt
count, I think you should check irq_disabled() whole this process, put below
here.
if (unlikely(!irq_disabled()))
return;
Since irq_disabled() will be checked in irq_trace() anyway, so no problem
to return here when !irq_disabled().
> + /*
> + * Tracepoint probes are expected to be called with preempt disabled,
> + * We don't care about being called with preempt disabled but we need
> + * to know in the future if that changes so we can remove the next
> + * preempt_enable.
> + */
> + WARN_ON_ONCE(!preempt_count());
> +
> + /* Tracepoint probes disable preemption atleast once, account for that */
* Even we do this here, we are sure that irq is disabled in this context.
* which means preemption is kept disabled.
> + preempt_enable_notrace();
> +
> if (!preempt_trace() && irq_trace())
> stop_critical_timing(a0, a1);
> +
> + preempt_disable_notrace();
> }
>
> static void tracer_hardirqs_off(void *none, unsigned long a0, unsigned long a1)
> {
Same here.
Any though :) ?
Thank you,
> + /*
> + * Tracepoint probes are expected to be called with preempt disabled,
> + * We don't care about being called with preempt disabled but we need
> + * to know in the future if that changes so we can remove the next
> + * preempt_enable.
> + */
> + WARN_ON_ONCE(!preempt_count());
> +
> + /* Tracepoint probes disable preemption atleast once, account for that */
> + preempt_enable_notrace();
> +
> if (!preempt_trace() && irq_trace())
> start_critical_timing(a0, a1);
> +
> + preempt_disable_notrace();
> }
>
> static int irqsoff_tracer_init(struct trace_array *tr)
> --
> 2.18.0.597.ga71716f1ad-goog
>
--
Masami Hiramatsu <[email protected]>
On Mon, Aug 6, 2018 at 7:05 AM, Masami Hiramatsu <[email protected]> wrote:
> On Sun, 5 Aug 2018 20:40:49 -0700
> "Joel Fernandes (Google)" <[email protected]> wrote:
>
>> Recently we tried to make the preemptirqsoff tracer to use irqsoff
>> tracepoint probes. However this causes issues as reported by Masami:
>>
>> [2.271078] Testing tracer preemptirqsoff: .. no entries found ..FAILED!
>> [2.381015] WARNING: CPU: 0 PID: 1 at /home/mhiramat/ksrc/linux/kernel/
>> trace/trace.c:1512 run_tracer_selftest+0xf3/0x154
>>
>> This is due to the tracepoint code increasing the preempt nesting count
>> by calling an additional preempt_disable before calling into the
>> preemptoff tracer which messes up the preempt_count() check in
>> tracer_hardirqs_off.
>>
>> To fix this, make the irqsoff tracer probes balance the additional outer
>> preempt_disable with a preempt_enable_notrace.
>
> I've tested it and ensured this fixes the problem.
>
> Tested-by: Masami Hiramatsu <[email protected]>
Thanks!
>> The other way to fix this is to just use SRCU for all tracepoints.
>> However we can't do that because we can't use NMIs from RCU context.
>>
>> Fixes: c3bc8fd637a9 ("tracing: Centralize preemptirq tracepoints
>> and unify their usage")
>> Fixes: e6753f23d961 ("tracepoint: Make rcuidle tracepoint callers use SRCU")
>> Reported-by: Masami Hiramatsu <[email protected]>
>> Signed-off-by: Joel Fernandes (Google) <[email protected]>
>> ---
>> kernel/trace/trace_irqsoff.c | 26 ++++++++++++++++++++++++++
>> 1 file changed, 26 insertions(+)
>>
>> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
>> index 770cd30cda40..ffbf1505d5bc 100644
>> --- a/kernel/trace/trace_irqsoff.c
>> +++ b/kernel/trace/trace_irqsoff.c
>> @@ -603,14 +603,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
>> */
>> static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
>> {
>
> To ensure this function must not be preempted even if we increment preempt
> count, I think you should check irq_disabled() whole this process, put below
> here.
>
> if (unlikely(!irq_disabled()))
> return;
>
> Since irq_disabled() will be checked in irq_trace() anyway, so no problem
> to return here when !irq_disabled().
IRQs can never be enabled here. The trace hooks are called only after
disabling interrupts, or before enabling them. Right?
thanks,
- Joel
On Fri, 10 Aug 2018 06:01:34 -0700
Joel Fernandes <[email protected]> wrote:
> > Even though, it should be verified or atleast commented on the function header.
>
> Ok. ftrace/core has been fixed since since so this patch is outdated
> and isn't needed any more, but I agree a separate patch doc comment
> would help make it clear about this fact. Both IRQ and preempt
> tracepoints work this way, they fire only within their critical
> section.
Note, I'm keeping the patch in the git history. As an artifact that can
be found easily when looking at this code for further enhancements.
Feel free to send a patch that adds comments to these callbacks.
-- Steve
On Mon, 6 Aug 2018 07:14:35 -0700
Joel Fernandes <[email protected]> wrote:
> On Mon, Aug 6, 2018 at 7:05 AM, Masami Hiramatsu <[email protected]> wrote:
> > On Sun, 5 Aug 2018 20:40:49 -0700
> > "Joel Fernandes (Google)" <[email protected]> wrote:
> >
> >> Recently we tried to make the preemptirqsoff tracer to use irqsoff
> >> tracepoint probes. However this causes issues as reported by Masami:
> >>
> >> [2.271078] Testing tracer preemptirqsoff: .. no entries found ..FAILED!
> >> [2.381015] WARNING: CPU: 0 PID: 1 at /home/mhiramat/ksrc/linux/kernel/
> >> trace/trace.c:1512 run_tracer_selftest+0xf3/0x154
> >>
> >> This is due to the tracepoint code increasing the preempt nesting count
> >> by calling an additional preempt_disable before calling into the
> >> preemptoff tracer which messes up the preempt_count() check in
> >> tracer_hardirqs_off.
> >>
> >> To fix this, make the irqsoff tracer probes balance the additional outer
> >> preempt_disable with a preempt_enable_notrace.
> >
> > I've tested it and ensured this fixes the problem.
> >
> > Tested-by: Masami Hiramatsu <[email protected]>
>
> Thanks!
>
> >> The other way to fix this is to just use SRCU for all tracepoints.
> >> However we can't do that because we can't use NMIs from RCU context.
> >>
> >> Fixes: c3bc8fd637a9 ("tracing: Centralize preemptirq tracepoints
> >> and unify their usage")
> >> Fixes: e6753f23d961 ("tracepoint: Make rcuidle tracepoint callers use SRCU")
> >> Reported-by: Masami Hiramatsu <[email protected]>
> >> Signed-off-by: Joel Fernandes (Google) <[email protected]>
> >> ---
> >> kernel/trace/trace_irqsoff.c | 26 ++++++++++++++++++++++++++
> >> 1 file changed, 26 insertions(+)
> >>
> >> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> >> index 770cd30cda40..ffbf1505d5bc 100644
> >> --- a/kernel/trace/trace_irqsoff.c
> >> +++ b/kernel/trace/trace_irqsoff.c
> >> @@ -603,14 +603,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
> >> */
> >> static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
> >> {
> >
> > To ensure this function must not be preempted even if we increment preempt
> > count, I think you should check irq_disabled() whole this process, put below
> > here.
> >
> > if (unlikely(!irq_disabled()))
> > return;
> >
> > Since irq_disabled() will be checked in irq_trace() anyway, so no problem
> > to return here when !irq_disabled().
>
> IRQs can never be enabled here. The trace hooks are called only after
> disabling interrupts, or before enabling them. Right?
>
Even though, it should be verified or atleast commented on the function header.
Thank you,
--
Masami Hiramatsu <[email protected]>
On Fri, Aug 10, 2018 at 5:55 AM, Masami Hiramatsu <[email protected]> wrote:
[..]
>>
>> >> The other way to fix this is to just use SRCU for all tracepoints.
>> >> However we can't do that because we can't use NMIs from RCU context.
>> >>
>> >> Fixes: c3bc8fd637a9 ("tracing: Centralize preemptirq tracepoints
>> >> and unify their usage")
>> >> Fixes: e6753f23d961 ("tracepoint: Make rcuidle tracepoint callers use SRCU")
>> >> Reported-by: Masami Hiramatsu <[email protected]>
>> >> Signed-off-by: Joel Fernandes (Google) <[email protected]>
>> >> ---
>> >> kernel/trace/trace_irqsoff.c | 26 ++++++++++++++++++++++++++
>> >> 1 file changed, 26 insertions(+)
>> >>
>> >> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
>> >> index 770cd30cda40..ffbf1505d5bc 100644
>> >> --- a/kernel/trace/trace_irqsoff.c
>> >> +++ b/kernel/trace/trace_irqsoff.c
>> >> @@ -603,14 +603,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
>> >> */
>> >> static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
>> >> {
>> >
>> > To ensure this function must not be preempted even if we increment preempt
>> > count, I think you should check irq_disabled() whole this process, put below
>> > here.
>> >
>> > if (unlikely(!irq_disabled()))
>> > return;
>> >
>> > Since irq_disabled() will be checked in irq_trace() anyway, so no problem
>> > to return here when !irq_disabled().
>>
>> IRQs can never be enabled here. The trace hooks are called only after
>> disabling interrupts, or before enabling them. Right?
>>
>
> Even though, it should be verified or atleast commented on the function header.
Ok. ftrace/core has been fixed since since so this patch is outdated
and isn't needed any more, but I agree a separate patch doc comment
would help make it clear about this fact. Both IRQ and preempt
tracepoints work this way, they fire only within their critical
section.