tracing: Don't account for cpu idle time with irqsoff tracers

Quoted 8 lines · On Tuesday 27 May 2014 13:08:04 Stephen Boyd wrote:

kernel/trace/trace_irqsoff.c +1 -1

@@ -380,7 +382,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 
        cpu = raw_smp_processor_id();
 
-       if (per_cpu(tracing_cpu, cpu))
+       if (per_cpu(timings_stopped, cpu) || per_cpu(tracing_cpu, cpu))
                return;
 

Review start_critical_timing(unsigned long ip, unsigned long parent_ip) · line 388

Quoted 2 lines

(quoted diff) +0 -0

        data = per_cpu_ptr(tr->trace_buffer.data, cpu);

Where exactly do you see other code calling here while per_cpu(timings_stopped) is set? Would it be possible to just change that call site?

Quoted 9 lines · On Tue, 27 May 2014 22:11:25 +0200 Arnd Bergmann <[email protected]> wrote:

Quoted 8 lines · On Tuesday 27 May 2014 13:08:04 Stephen Boyd wrote:

kernel/trace/trace_irqsoff.c +1 -1

@@ -380,7 +382,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 
        cpu = raw_smp_processor_id();
 
-       if (per_cpu(tracing_cpu, cpu))
+       if (per_cpu(timings_stopped, cpu) || per_cpu(tracing_cpu, cpu))
                return;
 

Quoted 5 lines

Review start_critical_timing(unsigned long ip, unsigned long parent_ip) · line 388

Quoted 2 lines

(quoted diff) +0 -0

        data = per_cpu_ptr(tr->trace_buffer.data, cpu);

Where exactly do you see other code calling here while per_cpu(timings_stopped) is set? Would it be possible to just change that call site?

Arnd brings up a good point.

If we disable irqs off tracing completely,
we may be missing places in the idle path that disable interrupts for long periods of time. We may want to move the stop down further.

The way it works (IIRC), and why tracing can start again is that it can nest. Perhaps we need to stop it further down if we can't move it completely.

Quoted 1 line

Arnd brings up a good point.

Hrm.. still not getting Arnd's mails.

Quoted 9 lines

If we disable irqs off tracing completely,
we may be missing places in the idle path that disable interrupts for long periods of time. We may want to move the stop down further.

The way it works (IIRC), and why tracing can start again is that it can nest. Perhaps we need to stop it further down if we can't move it completely.

I'm not sure how much deeper it can go and I'm afraid it will become a game of whack-a-mole. I already see two places that disable and reenable irqs after stop_critical_timings() is called (first in rcu_idle_enter() and second in clockevents_notify()). Should rcu_idle_enter() move to raw_local_irq_save()? It looks like that path calls rcu_sched_qs() and on tiny RCU that again needs the raw_ treatement. We can probably call stop_critical_timings() after rcu_idle_enter() to fix this.

What about clockevents_notify? __raw_spin_lock_irqsave() should probably use raw_local_irqsave().

If we go the raw route, do we even need stop/start_critical_timings()? Can't we just use raw accessors in the idle paths (tick_nohz_idle_{enter,exit}(), cpuidle_enter(), etc.) and get rid of the stop/start stuff completely? I admit this patch is pretty much a big sledge hammer that tries to make things simple, but if there is some benefit to the raw accessors I'm willing to send patches to fix all the call sites.

Quoted 2 lines · On Tue, 27 May 2014 15:21:39 -0700 Stephen Boyd <[email protected]> wrote:

Quoted 1 line

Arnd brings up a good point.

Hrm.. still not getting Arnd's mails.

Strange. What mail service do you have. Could they be blocking him?

Quoted 8 lines

Quoted 8 lines

If we disable irqs off tracing completely,
we may be missing places in the idle path that disable interrupts for long periods of time. We may want to move the stop down further.

The way it works (IIRC), and why tracing can start again is that it can nest. Perhaps we need to stop it further down if we can't move it completely.

Quoted 7 lines

I'm not sure how much deeper it can go and I'm afraid it will become a game of whack-a-mole. I already see two places that disable and reenable irqs after stop_critical_timings() is called (first in rcu_idle_enter() and second in clockevents_notify()). Should rcu_idle_enter() move to raw_local_irq_save()? It looks like that path calls rcu_sched_qs() and on tiny RCU that again needs the raw_ treatement. We can probably call stop_critical_timings() after rcu_idle_enter() to fix this.

I don't think we need to whack-a-mole. The start stop should be around where it goes to sleep.

Quoted 2 lines

What about clockevents_notify? __raw_spin_lock_irqsave() should probably use raw_local_irqsave().

No that solution is even worse. We need lockdep working here.

Quoted 8 lines

If we go the raw route, do we even need stop/start_critical_timings()? Can't we just use raw accessors in the idle paths (tick_nohz_idle_{enter,exit}(), cpuidle_enter(), etc.) and get rid of the stop/start stuff completely? I admit this patch is pretty much a big sledge hammer that tries to make things simple, but if there is some benefit to the raw accessors I'm willing to send patches to fix all the call sites.

How about the following. I don't see any reason stop_critical_timings() can't be called from within rcu_idle code, as it doesn't use any rcu.

Paul, Peter, see anything wrong with this?

Quoted 38 lines · Steven Rostedt

Quoted 2 lines · On Tue, 27 May 2014 15:21:39 -0700 Stephen Boyd <[email protected]> wrote:

Quoted 1 line

Arnd brings up a good point.

Hrm.. still not getting Arnd's mails.

Strange. What mail service do you have. Could they be blocking him?

Quoted 8 lines

Quoted 8 lines

If we disable irqs off tracing completely,
we may be missing places in the idle path that disable interrupts for long periods of time. We may want to move the stop down further.

The way it works (IIRC), and why tracing can start again is that it can nest. Perhaps we need to stop it further down if we can't move it completely.

Quoted 7 lines

I'm not sure how much deeper it can go and I'm afraid it will become a game of whack-a-mole. I already see two places that disable and reenable irqs after stop_critical_timings() is called (first in rcu_idle_enter() and second in clockevents_notify()). Should rcu_idle_enter() move to raw_local_irq_save()? It looks like that path calls rcu_sched_qs() and on tiny RCU that again needs the raw_ treatement. We can probably call stop_critical_timings() after rcu_idle_enter() to fix this.

I don't think we need to whack-a-mole. The start stop should be around where it goes to sleep.

Quoted 2 lines

What about clockevents_notify? __raw_spin_lock_irqsave() should probably use raw_local_irqsave().

No that solution is even worse. We need lockdep working here.

Quoted 8 lines

If we go the raw route, do we even need stop/start_critical_timings()? Can't we just use raw accessors in the idle paths (tick_nohz_idle_{enter,exit}(), cpuidle_enter(), etc.) and get rid of the stop/start stuff completely? I admit this patch is pretty much a big sledge hammer that tries to make things simple, but if there is some benefit to the raw accessors I'm willing to send patches to fix all the call sites.

Quoted 5 lines

How about the following. I don't see any reason stop_critical_timings() can't be called from within rcu_idle code, as it doesn't use any rcu.

Paul, Peter, see anything wrong with this?

cpuidle_enter_state() calls ktime_get() which on lockdep enabled builds calls seqcount_lockdep_reader_access() which calls local_irq_save() that then turns on the tracer again. Perhaps the problem is that irqsoff tracer is triggered even when we aren't transitioning between irqs on and irqs off? What about this patch? I assume there is a reason that this is wrong, but I don't know what it is.

---8<-----

include/linux/irqflags.h +2 -1

index d176d658fe25..ac8e0a4968bd 100644
@@ -93,7 +93,8 @@
 #define local_irq_save(flags)				\
 	do {						\
 		raw_local_irq_save(flags);		\
-		trace_hardirqs_off();			\
+		if (!raw_irqs_disabled_flags(flags))	\
+			trace_hardirqs_off();		\
 	} while (0)
 
 

cpuidle_enter_state() calls ktime_get() which on lockdep enabled builds calls seqcount_lockdep_reader_access() which calls local_irq_save() that

then turns on the tracer again. Perhaps the problem is that irqsoff tracer is triggered even when we aren't transitioning between irqs on and irqs off? What about this patch? I assume there is a reason that this is wrong, but I don't know what it is.

Quoted 2 lines · Stephen Boyd

cpuidle_enter_state() calls ktime_get() which on lockdep enabled builds calls seqcount_lockdep_reader_access() which calls local_irq_save() that

seqcount_lockdep_reader_access()?? Ug, I wonder if that should call raw_local_irq_save/restore() as it's a lockdep helper to begin with. If it's wrong then it's the lockdep infrastructure that broke, not the core kernel.

Peter?

Quoted 11 lines · Steven Rostedt

Quoted 2 lines · Stephen Boyd

cpuidle_enter_state() calls ktime_get() which on lockdep enabled builds calls seqcount_lockdep_reader_access() which calls local_irq_save() that

seqcount_lockdep_reader_access()?? Ug, I wonder if that should call raw_local_irq_save/restore() as it's a lockdep helper to begin with. If it's wrong then it's the lockdep infrastructure that broke, not the core kernel.

Peter?

Hurm,.. don't know actually.. so from a lockdep pov it doesn't need to do that and we can simply remove the local_irq_{save,restore}() from that function.

It could be John did it to avoid some IRQ recursion warning, but if so, he failed to mention it.

John, remember why you typed those characters?

Quoted 3 lines · On Tue, 27 May 2014 15:21:39 -0700 Stephen Boyd <[email protected]> wrote:

Quoted 1 line

Arnd brings up a good point.

Hrm.. still not getting Arnd's mails.

Strange. What mail service do you have. Could they be blocking him?

Quoted 10 lines

Quoted 9 lines

If we disable irqs off tracing completely,
we may be missing places in the idle path that disable interrupts for long periods of time. We may want to move the stop down further.

The way it works (IIRC), and why tracing can start again is that it can nest. Perhaps we need to stop it further down if we can't move it completely.

Quoted 7 lines

I'm not sure how much deeper it can go and I'm afraid it will become a game of whack-a-mole. I already see two places that disable and reenable irqs after stop_critical_timings() is called (first in rcu_idle_enter() and second in clockevents_notify()). Should rcu_idle_enter() move to raw_local_irq_save()? It looks like that path calls rcu_sched_qs() and on tiny RCU that again needs the raw_ treatement. We can probably call stop_critical_timings() after rcu_idle_enter() to fix this.

I don't think we need to whack-a-mole. The start stop should be around where it goes to sleep.

Quoted 3 lines

What about clockevents_notify? __raw_spin_lock_irqsave() should probably use raw_local_irqsave().

No that solution is even worse. We need lockdep working here.

Quoted 9 lines

If we go the raw route, do we even need stop/start_critical_timings()? Can't we just use raw accessors in the idle paths (tick_nohz_idle_{enter,exit}(), cpuidle_enter(), etc.) and get rid of the stop/start stuff completely? I admit this patch is pretty much a big sledge hammer that tries to make things simple, but if there is some benefit to the raw accessors I'm willing to send patches to fix all the call sites.

How about the following. I don't see any reason stop_critical_timings() can't be called from within rcu_idle code, as it doesn't use any rcu.

Paul, Peter, see anything wrong with this?

-- Steve

kernel/sched/idle.c +12 -8

index 8f4390a..f5e6a64 100644
@@ -88,12 +88,6 @@ static int cpuidle_idle_call(void)
 	}
 
 	/*
-	 * During the idle period, stop measuring the disabled irqs
-	 * critical sections latencies
-	 */
-	stop_critical_timings();
-
-	/*
 	 * Tell the RCU framework we are entering an idle section,
 	 * so no more rcu read side critical sections and one more
 	 * step to the grace period

@@ -144,6 +138,12 @@ static int cpuidle_idle_call(void)
 				trace_cpu_idle_rcuidle(next_state, dev->cpu);
 
 				/*
+				 * During the idle period, stop measuring the
+				 * disabled irqs critical sections latencies
+				 */
+				stop_critical_timings();
+
+				/*
 				 * Enter the idle state previously
 				 * returned by the governor
 				 * decision. This function will block

@@ -154,6 +154,8 @@ static int cpuidle_idle_call(void)
 				entered_state = cpuidle_enter(drv, dev,
 							      next_state);
 
+				start_critical_timings();
+
 				trace_cpu_idle_rcuidle(PWR_EVENT_EXIT,
 						       dev->cpu);
 

@@ -175,8 +177,11 @@ static int cpuidle_idle_call(void)
 	 * We can't use the cpuidle framework, let's use the default
 	 * idle routine
 	 */
-	if (ret)
+	if (ret) {
+		stop_critical_timings();
 		arch_cpu_idle();
+		start_critical_timings();
+	}
 
 	__current_set_polling();
 

@@ -188,7 +193,6 @@ static int cpuidle_idle_call(void)
 		local_irq_enable();
 
 	rcu_idle_exit();
-	start_critical_timings();
 
 	return 0;
 }

Quoted 3 lines · On Tue, 27 May 2014 15:21:39 -0700 Stephen Boyd <[email protected]> wrote:

Quoted 1 line

Arnd brings up a good point.

Hrm.. still not getting Arnd's mails.

Strange. What mail service do you have. Could they be blocking him?

kernel/sched/idle.c +6 -0

@@ -144,6 +138,12 @@ static int cpuidle_idle_call(void)
                                trace_cpu_idle_rcuidle(next_state, dev->cpu);
 
                                /*
+                                * During the idle period, stop measuring the
+                                * disabled irqs critical sections latencies
+                                */
+                               stop_critical_timings();
+
+                               /*
                                 * Enter the idle state previously
                                 * returned by the governor
                                 * decision. This function will block

kernel/sched/idle.c +0 -0

@@ -175,8 +177,11 @@ static int cpuidle_idle_call(void)
         * We can't use the cpuidle framework, let's use the default
         * idle routine

Paul, Peter, see anything wrong with this?

kernel/sched/idle.c +8 -6

index 8f4390a..f5e6a64 100644
@@ -88,12 +88,6 @@ static int cpuidle_idle_call(void)
 	}
 
 	/*
-	 * During the idle period, stop measuring the disabled irqs
-	 * critical sections latencies
-	 */
-	stop_critical_timings();
-
-	/*
 	 * Tell the RCU framework we are entering an idle section,
 	 * so no more rcu read side critical sections and one more
 	 * step to the grace period

@@ -144,6 +138,12 @@ static int cpuidle_idle_call(void)
 				trace_cpu_idle_rcuidle(next_state, dev->cpu);
 
 				/*
+				 * During the idle period, stop measuring the
+				 * disabled irqs critical sections latencies
+				 */
+				stop_critical_timings();
+
+				/*
 				 * Enter the idle state previously
 				 * returned by the governor
 				 * decision. This function will block

@@ -154,6 +154,8 @@ static int cpuidle_idle_call(void)
 				entered_state = cpuidle_enter(drv, dev,
 							      next_state);
 
+				start_critical_timings();
+
 				trace_cpu_idle_rcuidle(PWR_EVENT_EXIT,
 						       dev->cpu);
 

Quoted 1 line · Steven Rostedt

Paul, Peter, see anything wrong with this?

You mean, aside from that it won't actually apply due to that code having been massively overhauled?

I suppose the same thing Arnd mentioned, the cpuidle_enter() thing can be huge, but is we're going to have to push this down into all cpuidle drivers we're not going to be happy.