tracing: Add trace events for preemption and irq disable/enable

include/trace/events/preemptirq.h new file +10 -0

+DECLARE_EVENT_CLASS(preemptirq_template,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip),
+
+	TP_ARGS(ip, parent_ip),
+
+	TP_STRUCT__entry(
+		__field(u32, caller_offs)
+		__field(u32, parent_offs)
+	),

kernel/trace/trace_irqsoff.c +12 -0

index 26c688740742..f3087e7278cb 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;

@@ -777,14 +780,29 @@ 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
 
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+static DEFINE_PER_CPU(int, tracing_preempt_cpu);
+
 void start_critical_timings(void)
 {
+	if (this_cpu_read(tracing_preempt_cpu))
+		trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+	if (this_cpu_read(tracing_irq_cpu))
+		trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
 	start_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);
 
 void stop_critical_timings(void)

kernel/trace/trace_irqsoff.c +32 -1

@@ -792,24 +810,48 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
 #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);

@@ -831,14 +873,27 @@ inline void print_irqtrace_events(struct task_struct *curr)
 }
 #endif
 
-#ifdef CONFIG_PREEMPT_TRACER
+#if defined(CONFIG_PREEMPT_TRACER) || \
+	(defined(CONFIG_DEBUG_PREEMPT) && defined(CONFIG_PREEMPTIRQ_EVENTS))
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
+	if (!this_cpu_read(tracing_preempt_cpu))
+		return;
+
+	trace_preempt_enable_rcuidle(a0, a1);
 	tracer_preempt_on(a0, a1);
+
+	this_cpu_write(tracing_preempt_cpu, 0);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)

Quoted 14 lines · Joel Fernandes

include/trace/events/preemptirq.h new file +14 -0

+DECLARE_EVENT_CLASS(preemptirq_template,
+
+     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+
+     TP_ARGS(ip, parent_ip),
+
+     TP_STRUCT__entry(
+             __field(u32, caller_offs)
+             __field(u32, parent_offs)
+     ),
+
+     TP_fast_assign(
+             __entry->caller_offs = (u32)(ip - (unsigned long)_stext);
+             __entry->parent_offs = (u32)(parent_ip - (unsigned long)_stext);

include/trace/events/preemptirq.h line 33

Quoted 6 lines

include/trace/events/preemptirq.h new file +6 -0

+     ),
+
+     TP_printk("caller=%pF parent=%pF",
+               (void *)((unsigned long)(_stext) + __entry->caller_offs),
+               (void *)((unsigned long)(_stext) + __entry->parent_offs))
+);

So I don't get that function prototype. Why do we need two IPs?

Quoted 34 lines

kernel/trace/trace_irqsoff.c +12 -0

index 26c688740742..f3087e7278cb 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;

@@ -777,14 +780,29 @@ 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
 
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+static DEFINE_PER_CPU(int, tracing_preempt_cpu);
+
 void start_critical_timings(void)
 {
+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      start_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);
 

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

Quoted 11 lines

kernel/trace/trace_irqsoff.c +6 -0

 void stop_critical_timings(void)
 {
+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      stop_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);

And I feel these yield somewhat odd semantics, does that need explaining somewhere?

Quoted 27 lines

kernel/trace/trace_irqsoff.c +12 -0

@@ -792,24 +810,48 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
 #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);
 

kernel/trace/trace_irqsoff.c EXPORT_SYMBOL_GPL(stop_critical_timings);

Quoted 9 lines

kernel/trace/trace_irqsoff.c +6 -0

 __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_cpuHopefully I addressed your concern properly here?

Quoted 32 lines

kernel/trace/trace_irqsoff.c +14 -1

 }
 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);

@@ -831,14 +873,27 @@ inline void print_irqtrace_events(struct task_struct *curr)
 }
 #endif
 
-#ifdef CONFIG_PREEMPT_TRACER
+#if defined(CONFIG_PREEMPT_TRACER) || \
+     (defined(CONFIG_DEBUG_PREEMPT) && defined(CONFIG_PREEMPTIRQ_EVENTS))
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
+     if (!this_cpu_read(tracing_preempt_cpu))
+             return;
+
+     trace_preempt_enable_rcuidle(a0, a1);
      tracer_preempt_on(a0, a1);
+
+     this_cpu_write(tracing_preempt_cpu, 0);
 }
 

kernel/trace/trace_irqsoff.c inline void print_irqtrace_events(struct task_struct *curr) · line 899

Quoted 11 lines

kernel/trace/trace_irqsoff.c +6 -0

 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
+     if (this_cpu_read(tracing_preempt_cpu))
+             return;
+
+     this_cpu_write(tracing_preempt_cpu, 1);
+
+     trace_preempt_disable_rcuidle(a0, a1);
      tracer_preempt_off(a0, a1);
 }
 #endif

And here you assume things like double on / double off don't happen, which might well be so, but does seem somewhat fragile.

So all in all I don't see anything particularly wrong, but I see lots that could do with explaining.

Quoted 6 lines

include/trace/events/preemptirq.h line 33

Quoted 4 lines

include/trace/events/preemptirq.h new file +4 -0

+     TP_printk("caller=%pF parent=%pF",
+               (void *)((unsigned long)(_stext) + __entry->caller_offs),
+               (void *)((unsigned long)(_stext) + __entry->parent_offs))
+);

So I don't get that function prototype. Why do we need two IPs?

This follows the exact same "model" used by the preempt/irqsoff tracer. The rationale IIUC is a lot of times the actual preempt event is done by say a lock, but the actual caller of the lock function causing the preempt disable event is also of interest so this gives some more information of interest without needing the full stack, for example the spinlock acquiring in add_wait_queue disabled preemption here:

            grep-1041  [002] d..1    80.363455: preempt_disable:

caller=_raw_spin_lock_irqsave+0x1d/0x40
parent=add_wait_queue+0x15/0x50

Quoted 12 lines

Quoted 12 lines

void start_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      start_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);

Quoted 14 lines

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

Quoted 11 lines

void stop_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      stop_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);

And I feel these yield somewhat odd semantics, does that need explaining somewhere?

Maybe I can add a comment here, if you prefer that. When you meant semantics, do you mean 'critical' vs 'atomic' thing or do you mean the semantics/context of how this function is supposed to be used?

Quoted 6 lines

Quoted 6 lines

void trace_preempt_off(unsigned long a0, unsigned long a1) {

kernel/trace/trace_irqsoff.c +4 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             return;
+
+     this_cpu_write(tracing_preempt_cpu, 1);

Quoted 9 lines

kernel/trace/trace_irqsoff.c inline void print_irqtrace_events(struct task_struct *curr) · line 899

Quoted 5 lines

kernel/trace/trace_irqsoff.c +2 -0

+
+     trace_preempt_disable_rcuidle(a0, a1);
      tracer_preempt_off(a0, a1);
 }
 #endif

And here you assume things like double on / double off don't happen, which might well be so, but does seem somewhat fragile.

We are handling the cases where these functions might be called twice, but we are only interested in the first time they're called. I caught a dead lock happen when I didn't add such protection to trace_hardirqs_off so I added to these to the trace_hardirqs* and trace_preempt* ones as well to just to be extra safe and keep it consistent. Hope I understood your concern correctly, if not please let me know, thanks.

Quoted 4 lines

            grep-1041  [002] d..1    80.363455: preempt_disable:

caller=_raw_spin_lock_irqsave+0x1d/0x40
parent=add_wait_queue+0x15/0x50

I suppose that sort-of makes sense for the preempt-tracer, but its a weird thing for a generic tracepoint.

Quoted 28 lines

Quoted 13 lines

Quoted 13 lines

void start_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      start_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);

Quoted 14 lines

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

Quoted 11 lines

void stop_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      stop_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);  

And I feel these yield somewhat odd semantics, does that need explaining somewhere?

Quoted 3 lines

Maybe I can add a comment here, if you prefer that. When you meant semantics, do you mean 'critical' vs 'atomic' thing or do you mean the semantics/context of how this function is supposed to be used?

I would add the comment to the tracepoint definition.

On semantics, the whole stop/start excludes a fair bunch of walltime from our measurement, I feel that needs to be called out and enumerated (when time goes missing and why).

Given that the idle thread runs with preempt-off I understand its purpose from the POV from the preempt-tracer, but its 'weird' behaviour if you're looking at it from a pure tracepoint pov.

Quoted 17 lines

Quoted 16 lines

kernel/trace/trace_irqsoff.c inline void print_irqtrace_events(struct task_struct *curr) · line 899

Quoted 12 lines

void trace_preempt_off(unsigned long a0, unsigned long a1) {

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             return;
+
+     this_cpu_write(tracing_preempt_cpu, 1);
+
+     trace_preempt_disable_rcuidle(a0, a1);
      tracer_preempt_off(a0, a1);
 }
 #endif  

And here you assume things like double on / double off don't happen, which might well be so, but does seem somewhat fragile.

Quoted 7 lines

We are handling the cases where these functions might be called twice, but we are only interested in the first time they're called. I caught a dead lock happen when I didn't add such protection to trace_hardirqs_off so I added to these to the trace_hardirqs* and trace_preempt* ones as well to just to be extra safe and keep it consistent. Hope I understood your concern correctly, if not please let me know, thanks.

Under what conditions where they called twice? That seems like something that should not happen to begin with. Esp the one I left quoted above, disabling when its already disabled sounds like fail. So please provide more details on the scenario you're working around.

Quoted 1 line · On Mon, 25 Sep 2017 10:34:32 +0200 Peter Zijlstra <[email protected]> wrote:

Quoted 1 line

Quoted 6 lines

Quoted 3 lines

            grep-1041  [002] d..1    80.363455: preempt_disable:

caller=_raw_spin_lock_irqsave+0x1d/0x40
parent=add_wait_queue+0x15/0x50

I suppose that sort-of makes sense for the preempt-tracer, but its a weird thing for a generic tracepoint.

I still find it very useful, even as a tracepoint.

Quoted 6 lines

I would add the comment to the tracepoint definition.

On semantics, the whole stop/start excludes a fair bunch of walltime from our measurement, I feel that needs to be called out and enumerated (when time goes missing and why).

Quoted 3 lines

Given that the idle thread runs with preempt-off I understand its purpose from the POV from the preempt-tracer, but its 'weird' behaviour if you're looking at it from a pure tracepoint pov.

You mean you want to trace all calls to preempt and irq off even if preempt and irqs are already off?

Quoted 2 lines

You mean you want to trace all calls to preempt and irq off even if preempt and irqs are already off?

Sure, why not? This stuff naturally nests, and who is to say its not a useful thing to trace all of them?

By also tracing the nested sections you can, for instance, see how much you'd really win by getting rid of the outer one. If, for instance, the outer only accounts for 1% of the time, while the inner ones are interlinked and span the other 99%, there's more work to do than if that were not the case.

Quoted 11 lines · On Mon, 25 Sep 2017 12:32:23 +0200 Peter Zijlstra <[email protected]> wrote:

Quoted 2 lines

You mean you want to trace all calls to preempt and irq off even if preempt and irqs are already off?

Sure, why not? This stuff naturally nests, and who is to say its not a useful thing to trace all of them?

By also tracing the nested sections you can, for instance, see how much you'd really win by getting rid of the outer one. If, for instance, the outer only accounts for 1% of the time, while the inner ones are interlinked and span the other 99%, there's more work to do than if that were not the case.

If we do this we need a field to record if the preemption or irqs were toggled by that call. Something that filters could easily be added to only show what this patch set has.

2. This stuff is already a bit trace heavy, I prefer not to generate event every time the preempt count increases. Ofcourse filters but still then we have the filtering overhead for a usecase that I am not really targetting with this patchset.

Quoted 16 lines · Steven Rostedt

Quoted 11 lines · On Mon, 25 Sep 2017 12:32:23 +0200 Peter Zijlstra <[email protected]> wrote:

Quoted 2 lines

You mean you want to trace all calls to preempt and irq off even if preempt and irqs are already off?

Sure, why not? This stuff naturally nests, and who is to say its not a useful thing to trace all of them?

By also tracing the nested sections you can, for instance, see how much you'd really win by getting rid of the outer one. If, for instance, the outer only accounts for 1% of the time, while the inner ones are interlinked and span the other 99%, there's more work to do than if that were not the case.

Quoted 3 lines

If we do this we need a field to record if the preemption or irqs were toggled by that call. Something that filters could easily be added to only show what this patch set has.

I request that we please not do this for my patchset, there are a number of reasons in my mind:

1. trace_preempt_off in existing code is only called the first time preempt is turned off. This is the definition of "preempt off", its the first time Preemption is actually turned off, and has nothing much to do with going into a deeper preempt count. Whether the count increases or not, preempt is already off and that's confirmed by the first preempt off event.

This is how I read it in the comments in sched/core.c as well:
"
* If the value passed in is equal to the current preempt count
* then we just disabled preemption."

This is how I based this patchset as well, againt its not my usecase and it can be a future patch if its useful to track this.

2. This stuff is already a bit trace heavy, I prefer not to generate event every time the preempt count increases. Ofcourse filters but still then we have the filtering overhead for a usecase that I am not really targetting with this patchset.

3. It will complicate the patch more, apart from adding filters as Steven suggested, it would also mean we change how preempt_latency_start in sched/core.c works.

Do you mind if we please keep this as a 'future' usecase for a future patch? Its not my usecase at all for this patchset and not what I was intending.

I will reply to Peter's other comments on the other email shortly.

thanks!

- Joel

On Fri, Sep 22, 2017 at 11:28:30AM -0700, Joel Fernandes wrote:

Quoted 27 lines

Quoted 12 lines

Quoted 12 lines

void start_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      start_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);

Quoted 14 lines

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

Quoted 11 lines

void stop_critical_timings(void)
{

kernel/trace/trace_irqsoff.c +6 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
+     if (this_cpu_read(tracing_irq_cpu))
+             trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+
      stop_critical_timings_tracer();
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);

And I feel these yield somewhat odd semantics, does that need explaining somewhere?

Quoted 3 lines

Maybe I can add a comment here, if you prefer that. When you meant semantics, do you mean 'critical' vs 'atomic' thing or do you mean the semantics/context of how this function is supposed to be used?

I would add the comment to the tracepoint definition.

On semantics, the whole stop/start excludes a fair bunch of walltime from our measurement, I feel that needs to be called out and enumerated (when time goes missing and why).

Given that the idle thread runs with preempt-off I understand its purpose from the POV from the preempt-tracer, but its 'weird' behaviour if you're looking at it from a pure tracepoint pov.

Quoted 16 lines

Quoted 6 lines

Quoted 6 lines

void trace_preempt_off(unsigned long a0, unsigned long a1) {

kernel/trace/trace_irqsoff.c +4 -0

+     if (this_cpu_read(tracing_preempt_cpu))
+             return;
+
+     this_cpu_write(tracing_preempt_cpu, 1);

Quoted 9 lines

kernel/trace/trace_irqsoff.c inline void print_irqtrace_events(struct task_struct *curr) · line 899

Quoted 5 lines

kernel/trace/trace_irqsoff.c +2 -0

+
+     trace_preempt_disable_rcuidle(a0, a1);
      tracer_preempt_off(a0, a1);
 }
 #endif

And here you assume things like double on / double off don't happen, which might well be so, but does seem somewhat fragile.

Quoted 7 lines

We are handling the cases where these functions might be called twice, but we are only interested in the first time they're called. I caught a dead lock happen when I didn't add such protection to trace_hardirqs_off so I added to these to the trace_hardirqs* and trace_preempt* ones as well to just to be extra safe and keep it consistent. Hope I understood your concern correctly, if not please let me know, thanks.

Under what conditions where they called twice? That seems like something that should not happen to begin with. Esp the one I left quoted above,

disabling when its already disabled sounds like fail. So please provide more details on the scenario you're working around.

The trace_hardirqs_off API can be called even when IRQs are already off. This is unlike the trace_hardirqs_on which checks if IRQs are off (atleast from some callsites), here are the definitions just for reference [1]. I guess we could modify local_irq_disable and local_irq_save to check what the HW flags was before calling raw_local_irq_save and only then call trace_hardirqs_off if they were indeed on and now being turned off, but that adds complexity to it - also we have to then modify all the callsites from assembly code to conditionally call trace_hardirqs_on/off :(.

[1] http://elixir.free-electrons.com/linux/latest/source/include/linux/irqflags.h#L89

Quoted 11 lines · On Mon, 25 Sep 2017 17:23:00 -0700 Joel Fernandes <[email protected]> wrote:

The trace_hardirqs_off API can be called even when IRQs are already off. This is unlike the trace_hardirqs_on which checks if IRQs are off (atleast from some callsites), here are the definitions just for reference [1]. I guess we could modify local_irq_disable and local_irq_save to check what the HW flags was before calling raw_local_irq_save and only then call trace_hardirqs_off if they were indeed on and now being turned off, but that adds complexity to it - also we have to then modify all the callsites from assembly code to conditionally call trace_hardirqs_on/off :(.

Quoted 1 line

[1] http://elixir.free-electrons.com/linux/latest/source/include/linux/irqflags.h#L89

Yeah, I think the issue for the recursion is basically this:

#define local_irq_restore(flags)                        \
        do {                                            \
                if (raw_irqs_disabled_flags(flags)) {   \
                        raw_local_irq_restore(flags);   \
                        trace_hardirqs_off();           \
                } else {                                \
                        trace_hardirqs_on();            \
                        raw_local_irq_restore(flags);   \
                }                                       \
        } while (0)

Peter,

Is there any place where we would call local_irq_restore() when interrupts are enabled?

Hi Steven,

Quoted 30 lines · Steven Rostedt

Quoted 11 lines · On Mon, 25 Sep 2017 17:23:00 -0700 Joel Fernandes <[email protected]> wrote:

The trace_hardirqs_off API can be called even when IRQs are already off. This is unlike the trace_hardirqs_on which checks if IRQs are off (atleast from some callsites), here are the definitions just for reference [1]. I guess we could modify local_irq_disable and local_irq_save to check what the HW flags was before calling raw_local_irq_save and only then call trace_hardirqs_off if they were indeed on and now being turned off, but that adds complexity to it - also we have to then modify all the callsites from assembly code to conditionally call trace_hardirqs_on/off :(.

Quoted 1 line

[1] http://elixir.free-electrons.com/linux/latest/source/include/linux/irqflags.h#L89

Yeah, I think the issue for the recursion is basically this:

#define local_irq_restore(flags)                        \
        do {                                            \
                if (raw_irqs_disabled_flags(flags)) {   \
                        raw_local_irq_restore(flags);   \
                        trace_hardirqs_off();           \
                } else {                                \
                        trace_hardirqs_on();            \
                        raw_local_irq_restore(flags);   \
                }                                       \
        } while (0)

Quoted 4 lines

Peter,

Is there any place where we would call local_irq_restore() when interrupts are enabled?

Actually local_irq_restore doesn't have the problem I describe since we do check for 'flags' and based on the condition and *only* then call the trace_hardirqs_* functions right?

include/linux/irqflags.h +3 -1

index 5dd1272d1ab2..2a1af0dd9cc4 100644
@@ -93,7 +93,9 @@
 #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)
 
 

Quoted 15 lines · On Mon, 2 Oct 2017 12:33:30 -0700 Joel Fernandes <[email protected]> wrote:

include/linux/irqflags.h +3 -1

index 5dd1272d1ab2..2a1af0dd9cc4 100644
@@ -93,7 +93,9 @@
 #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)
 
 

include/linux/irqflags.h line 108

Quoted 8 lines

include/linux/irqflags.h +0 -1

@@ -101,7 +103,6 @@
        do {                                            \
                if (raw_irqs_disabled_flags(flags)) {   \
                        raw_local_irq_restore(flags);   \
-                       trace_hardirqs_off();           \
                } else {                                \
                        trace_hardirqs_on();            \
                        raw_local_irq_restore(flags);   \

I rather have the protection in trace_hardirqs_on/off(). Let's keep the ugliness from spreading.

These patches add trace events support for preempt and irq disable/enable events.

Changes since v5:
- Use trace_*_rcuidle variants (thanks Steve!)

Here's an example of how Android's systrace will be using it to show critical sections as a gantt chart: http://imgur.com/download/TZplEVp

Links to earlier series:
v5: https://lkml.org/lkml/2017/9/12/507
v4: https://lkml.org/lkml/2017/9/6/724
v3: https://lkml.org/lkml/2017/9/3/15

Joel Fernandes (2):
tracing: Prepare to add preempt and irq trace events
tracing: Add support for preempt and irq enable/disable events

 include/linux/ftrace.h            |   3 +-
 include/linux/irqflags.h          |   4 +-
 include/trace/events/preemptirq.h |  66 ++++++++++++++
 kernel/trace/Kconfig              |   9 ++
 kernel/trace/Makefile             |   1 +
 kernel/trace/trace_irqsoff.c      | 176 +++++++++++++++++++++++++++++++-------
 6 files changed, 226 insertions(+), 33 deletions(-)
 create mode 100644 include/trace/events/preemptirq.h

Cc Steven Rostedt <[email protected]>

Cc Peter Zilstra <[email protected]>