tracing: Prepare to add preempt and irq trace events

kernel/trace/trace_irqsoff.c +3 -0

index 0e3033c00474..515ac851841a 100644
@@ -16,6 +16,9 @@
 
 #include "trace.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/preemptirq.h>
+
 #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;

kernel/trace/trace_irqsoff.c +27 -0

+ */
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
 #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
 void trace_hardirqs_on(void)
 {
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
 	tracer_hardirqs_on();
+
+	this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+
+	trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
 	tracer_hardirqs_off();
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
 	tracer_hardirqs_on_caller(caller_addr);
+
+	this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);
 
 __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
 {
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+
+	trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
 	tracer_hardirqs_off_caller(caller_addr);
 }

EXPORT_SYMBOL(trace_hardirqs_off_caller);

Quoted 15 lines · Joel Fernandes

kernel/trace/trace_irqsoff.c +3 -0

index 0e3033c00474..515ac851841a 100644
@@ -16,6 +16,9 @@
 
 #include "trace.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/preemptirq.h>
+
 #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
 static struct trace_array            *irqsoff_trace __read_mostly;
 static int                           tracer_enabled __read_mostly;

kernel/trace/trace_irqsoff.c static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { } · line 783

Quoted 5 lines

kernel/trace/trace_irqsoff.c +2 -0

@@ -776,27 +779,60 @@ static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
 static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
 #endif
 
+/*
+ * trace_hardirqs_off can be called even when IRQs are already off.

In fact it must be.. otherwise you'll get a complaint.

kernel/trace/trace_irqsoff.c static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { } · line 787

Quoted 5 lines

kernel/trace/trace_irqsoff.c +4 -0

    It is
+ * pointless and inconsistent with trace_preempt_enable and
+ * trace_preempt_disable to trace this, lets prevent double counting it with a
+ * per-cpu variable. Also reuse the per-cpu variable for other trace_hardirqs_*
+ * functions since we already define it.

Lockdep ignores redundant calls. But I'm not entirely sure what the above is trying to say.

Quoted 40 lines

kernel/trace/trace_irqsoff.c +21 -0

+ */
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
 #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
 void trace_hardirqs_on(void)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_on();
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_off();
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_on_caller(caller_addr);
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);
 

Quoted 11 lines

kernel/trace/trace_irqsoff.c +6 -0

 __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
 {
+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_off_caller(caller_addr);
 }

EXPORT_SYMBOL(trace_hardirqs_off_caller);

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

Quoted 40 lines

Quoted 40 lines

+ */

(quoted diff) +20 -0

+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
 #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
 void trace_hardirqs_on(void)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_on();
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_off();
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_on_caller(caller_addr);
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);

Quoted 14 lines

Review

Quoted 11 lines

__visible void trace_hardirqs_off_caller(unsigned long caller_addr) {

(quoted diff) +6 -0

+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_off_caller(caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

Yes, I think that makes sense and reduces code duplication, I can do this in the next rev.

On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:

Quoted 40 lines

+ */

kernel/trace/trace_irqsoff.c +20 -0

+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
 #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
 void trace_hardirqs_on(void)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_on();
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
      tracer_hardirqs_off();
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_on_caller(caller_addr);
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);

kernel/trace/trace_irqsoff.c static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { } · line 838

Quoted 11 lines

__visible void trace_hardirqs_off_caller(unsigned long caller_addr) {

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_off_caller(caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

Hi Peter,

Quoted 1 line · Peter Zijlstra

On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:

Quoted 14 lines

Quoted 14 lines

EXPORT_SYMBOL(trace_hardirqs_off);

__visible void trace_hardirqs_on_caller(unsigned long caller_addr) {

kernel/trace/trace_irqsoff.c +6 -0

+     if (!this_cpu_read(tracing_irq_cpu))
+             return;
+
+     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_on_caller(caller_addr);
+
+     this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);

Quoted 14 lines

kernel/trace/trace_irqsoff.c static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { } · line 838

Quoted 11 lines

__visible void trace_hardirqs_off_caller(unsigned long caller_addr) {

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_irq_cpu))
+             return;
+
+     this_cpu_write(tracing_irq_cpu, 1);
+
+     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
      tracer_hardirqs_off_caller(caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

In lockdep code, when trace_hardirqs_off is called, trace_hardirqs_off_caller would pass CALLER_ADDR0 as trace_hardirqs_off.

Because of this, the first argument passed to time_hardirqs_off would always be an offset within trace_hardirqs_off:
time_hardirqs_off(CALLER_ADDR0, ip);

Is that intended? Seems to me that in the lockdep implementation of trace_hardirqs_* in terms of *_caller(), we would completely miss the second-last return address (CALLER_ADDR1) of trace_hardirqs_off(). Also for the above reasons, I don't think it doesn't make sense to use this reuse logic for the tracer. Atleast I feel it might change the current behavior of the preempt/irqsoff tracer which I don't intend to

Quoted 2 lines

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

In lockdep code, when trace_hardirqs_off is called, trace_hardirqs_off_caller would pass CALLER_ADDR0 as trace_hardirqs_off.

Because of this, the first argument passed to time_hardirqs_off would always be an offset within trace_hardirqs_off:
time_hardirqs_off(CALLER_ADDR0, ip);

Is that intended? Seems to me that in the lockdep implementation of trace_hardirqs_* in terms of *_caller(), we would completely miss the second-last return address (CALLER_ADDR1) of trace_hardirqs_off(). Also for the above reasons, I don't think it doesn't make sense to use this reuse logic for the tracer. Atleast I feel it might change the current behavior of the preempt/irqsoff tracer which I don't intend to change with my current patch set.

Quoted 11 lines · Joel Fernandes

Quoted 2 lines

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would that make sense here?

In lockdep code, when trace_hardirqs_off is called, trace_hardirqs_off_caller would pass CALLER_ADDR0 as trace_hardirqs_off.

Because of this, the first argument passed to time_hardirqs_off would always be an offset within trace_hardirqs_off:
time_hardirqs_off(CALLER_ADDR0, ip);

Quoted 7 lines

Is that intended? Seems to me that in the lockdep implementation of trace_hardirqs_* in terms of *_caller(), we would completely miss the second-last return address (CALLER_ADDR1) of trace_hardirqs_off(). Also for the above reasons, I don't think it doesn't make sense to use this reuse logic for the tracer. Atleast I feel it might change the current behavior of the preempt/irqsoff tracer which I don't intend to change with my current patch set.

Hurm.. so I've no clue. I never looked at any of this. I think Ingo wrote that before I came joined the fun. He might (although unlikely, because its been _many_ years) still have some memories.

But given that lockdep enabled kernels never got those arguments right, how useful are they? I mean, nobody seems to have noticed much.

Oh ok. So I traced this down to the original patch that added time_hardirqs_off to lockdep. I *think* it was added just to keep the irqsoff tracer working while lockdep is enabled, so that both lockdep and the tracer would work at the same time. So I guess nobody noticed any issues because nobody noticed or cared to check if irqsoff tracer showed the same results with lockdep enabled vs disabled.

I think the correct way this should be rewritten is lockdep should use register_trace_* to register callbacks onto the new tracepoints I'm adding. I am working on a patch that does something like this and gets rid of the time_* functions. I will try to have an RFC out by the weekend if I hopefully don't hit any roadblocks.

thanks!

- Joel

Quoted 6 lines · On Fri, 6 Oct 2017 00:28:21 -0700 Joel Fernandes <[email protected]> wrote:

Oh ok. So I traced this down to the original patch that added time_hardirqs_off to lockdep. I *think* it was added just to keep the irqsoff tracer working while lockdep is enabled, so that both lockdep and the tracer would work at the same time. So I guess nobody noticed any issues because nobody noticed or cared to check if irqsoff tracer showed the same results with lockdep enabled vs disabled.

As one of the main users of preemptirqsoff tracer, I can tell you that we didn't care ;-)

Yes, it was added to keep them both working. It's dangerous to use CALLER_ADDR1, as lockdep can be called by the top frame, and ADDR1 would go off the stack frame and cause a fault. I just put in ADDR0 as filler as it required something to be added.

We added a stack dump on new max latencies to figure out where the problem occurred.

+++ b/kernel/trace/trace_irqsoff.c

EXPORT_SYMBOL(trace_hardirqs_on);
EXPORT_SYMBOL(trace_hardirqs_off);
EXPORT_SYMBOL(trace_hardirqs_on_caller);
EXPORT_SYMBOL(trace_hardirqs_off_caller);

Quoted 6 lines · Joel Fernandes

+++ b/kernel/trace/trace_irqsoff.c

EXPORT_SYMBOL(trace_hardirqs_on);
EXPORT_SYMBOL(trace_hardirqs_off);
EXPORT_SYMBOL(trace_hardirqs_on_caller);
EXPORT_SYMBOL(trace_hardirqs_off_caller);

Steve, how does this compiler with lockdep enabled? Because:

kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);

Quoted 6 lines · Joel Fernandes

+++ b/kernel/trace/trace_irqsoff.c

EXPORT_SYMBOL(trace_hardirqs_on);
EXPORT_SYMBOL(trace_hardirqs_off);
EXPORT_SYMBOL(trace_hardirqs_on_caller);
EXPORT_SYMBOL(trace_hardirqs_off_caller);

Steve, how does this compiler with lockdep enabled? Because:

kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);

Quoted 8 lines · On Wed, 4 Oct 2017 18:04:34 +0200 Peter Zijlstra <[email protected]> wrote:

Quoted 6 lines · Joel Fernandes

+++ b/kernel/trace/trace_irqsoff.c

EXPORT_SYMBOL(trace_hardirqs_on);
EXPORT_SYMBOL(trace_hardirqs_off);
EXPORT_SYMBOL(trace_hardirqs_on_caller);
EXPORT_SYMBOL(trace_hardirqs_off_caller);

Quoted 6 lines

Steve, how does this compiler with lockdep enabled? Because:

kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller); kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);

I'll have to see if it does, I haven't applied them yet. Looks like they were removed from the:

#ifdef CONFIG_PROVE_LOCKING

[..]

#else /* !CONFIG_PROVE_LOCKING */

<here>

#endif

I don't see the protection in the patches. I will definitely test that before pushing it anywhere.

Quoted 2 lines

I don't see the protection in the patches. I will definitely test that before pushing it anywhere.

The protection added by CONFIG_PROVE_LOCKING was already there before my patches. I just moved the code around in patch 1/2, nothing changed in that patch. I already tested the combination of PROVE_LOCKING enabled and disabled and several other combinations on your -next tree. It all compiled fine. Here is my test script FWIW:
(By the way, do you mean that another tree/branch than your -next or Linus's master has protection removed? If so, could you let me know which tree/branch?)

Quoted 11 lines · On Wed, 4 Oct 2017 09:56:33 -0700 Joel Fernandes <[email protected]> wrote:

Quoted 2 lines

I don't see the protection in the patches. I will definitely test that before pushing it anywhere.

The protection added by CONFIG_PROVE_LOCKING was already there before my patches. I just moved the code around in patch 1/2, nothing changed in that patch. I already tested the combination of PROVE_LOCKING enabled and disabled and several other combinations on your -next tree. It all compiled fine. Here is my test script FWIW:
(By the way, do you mean that another tree/branch than your -next or Linus's master has protection removed? If so, could you let me know which tree/branch?)

Using Linus's master is usually fine, but if you want to see what I'm working on, just look at the ftrace/core branch of my linux-trace.git tree on kernel.org. Note, that branch often rebases. My for-next branch does not.

Also note, I'm currently looking to pull in Tom Zanussi's hist patch series, and then I'll get to yours afterward.