[PATCH V2 1/2] trace,x86: Add external_interrupts to the irq_vectors class

[PATCH V2 1/2] trace,x86: Add external_interrupts to the irq_vectors class

[Daniel Bristot de Oliveira]

Currently, the irq_vectors is showing the entry and exit events for
the interrupts of the architecture, but not for external interrupts.

Adds the tracepoints for external interrupts.

Example of output:
 <idle>-0     [000] d.h.   102.890935: external_interrupt_entry: vector=35
 <idle>-0     [000] d.h.   102.890960: external_interrupt_exit: vector=35

Changes from V1:
  - Fix a compilation problem when CONFIG_X86_LOCAL_APIC is not set (kbuild test)

Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Andy Lutomirski <luto@kernel.org>
Cc: Clark Williams <williams@redhat.com>
Cc: linux-kernel@vger.kernel.org
Cc: x86@kernel.org
---
 arch/x86/include/asm/trace/irq_vectors.h | 10 +++++++++-
 arch/x86/kernel/irq.c                    |  2 ++
 2 files changed, 11 insertions(+), 1 deletion(-)

diff --git a/arch/x86/include/asm/trace/irq_vectors.h b/arch/x86/include/asm/trace/irq_vectors.h
index 33b9d0f0aafe..38e73d56db70 100644
--- a/arch/x86/include/asm/trace/irq_vectors.h
+++ b/arch/x86/include/asm/trace/irq_vectors.h
@@ -138,6 +138,12 @@ DEFINE_IRQ_VECTOR_EVENT(deferred_error_apic);
 DEFINE_IRQ_VECTOR_EVENT(thermal_apic);
 #endif
 
+/*
+ * external_interrupt - called when entering/exiting from regular device
+ * interrupt vector handler.
+ */
+DEFINE_IRQ_VECTOR_EVENT(external_interrupt);
+
 TRACE_EVENT(vector_config,
 
 	TP_PROTO(unsigned int irq, unsigned int vector,
@@ -385,7 +391,9 @@ TRACE_EVENT(vector_free_moved,
 		  __entry->is_managed)
 );
 
-
+#else /* CONFIG_X86_LOCAL_APIC */
+#define trace_external_interrupt_entry(vector) do {} while(0)
+#define trace_external_interrupt_exit(vector) do {} while(0)
 #endif /* CONFIG_X86_LOCAL_APIC */
 
 #undef TRACE_INCLUDE_PATH
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index 59b5f2ea7c2f..715afe3a4f24 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -237,6 +237,7 @@ __visible unsigned int __irq_entry do_IRQ(struct pt_regs *regs)
 	unsigned vector = ~regs->orig_ax;
 
 	entering_irq();
+	trace_external_interrupt_entry(vector);
 
 	/* entering_irq() tells RCU that we're not quiescent.  Check it. */
 	RCU_LOCKDEP_WARN(!rcu_is_watching(), "IRQ failed to wake up RCU");
@@ -255,6 +256,7 @@ __visible unsigned int __irq_entry do_IRQ(struct pt_regs *regs)
 		}
 	}
 
+	trace_external_interrupt_exit(vector);
 	exiting_irq();
 
 	set_irq_regs(old_regs);
-- 
2.19.0

[PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Daniel Bristot de Oliveira]

Currently, the irq_vector class of tracepoints does not include the NMI
entry. The NMI was in the first set of tracepoints for IRQs, but it was
dropped off because of the logic of switching IDT when enabling trace[1].
However, as the switching IDT logic was removed [2], it is possible to add
the NMI tracepoints back.

The tracepoints looks like:
          <idle>-0     [000] d.Z.   179.594315: nmi_entry: vector=2
          <idle>-0     [000] d.Z.   179.594396: nmi_exit: vector=2

[1] trace,x86: irq vector tracepoint support
    https://lwn.net/Articles/555465/
[2] commit 4b9a8dca0e58 ("x86/idt: Remove the tracing IDT completely")

Changes from V1:
  - Fix a compilation problem when CONFIG_X86_LOCAL_APIC is not set (kbuild test)

Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Andy Lutomirski <luto@kernel.org>
Cc: Clark Williams <williams@redhat.com>
Cc: linux-kernel@vger.kernel.org
Cc: x86@kernel.org
---
 arch/x86/include/asm/trace/irq_vectors.h | 7 +++++++
 arch/x86/kernel/nmi.c                    | 4 ++++
 2 files changed, 11 insertions(+)

diff --git a/arch/x86/include/asm/trace/irq_vectors.h b/arch/x86/include/asm/trace/irq_vectors.h
index 38e73d56db70..a68885e90e16 100644
--- a/arch/x86/include/asm/trace/irq_vectors.h
+++ b/arch/x86/include/asm/trace/irq_vectors.h
@@ -144,6 +144,11 @@ DEFINE_IRQ_VECTOR_EVENT(thermal_apic);
  */
 DEFINE_IRQ_VECTOR_EVENT(external_interrupt);
 
+/*
+ * nmi - called when entering/exiting from nmi vector handler.
+ */
+DEFINE_IRQ_VECTOR_EVENT(nmi);
+
 TRACE_EVENT(vector_config,
 
 	TP_PROTO(unsigned int irq, unsigned int vector,
@@ -394,6 +399,8 @@ TRACE_EVENT(vector_free_moved,
 #else /* CONFIG_X86_LOCAL_APIC */
 #define trace_external_interrupt_entry(vector) do {} while(0)
 #define trace_external_interrupt_exit(vector) do {} while(0)
+#define trace_nmi_entry(vector) do {} while(0)
+#define trace_nmi_exit(vector) do {} while(0)
 #endif /* CONFIG_X86_LOCAL_APIC */
 
 #undef TRACE_INCLUDE_PATH
diff --git a/arch/x86/kernel/nmi.c b/arch/x86/kernel/nmi.c
index 18bc9b51ac9b..fa2d16b3af60 100644
--- a/arch/x86/kernel/nmi.c
+++ b/arch/x86/kernel/nmi.c
@@ -37,6 +37,8 @@
 
 #define CREATE_TRACE_POINTS
 #include <trace/events/nmi.h>
+#undef CREATE_TRACE_POINTS
+#include <asm/trace/irq_vectors.h>
 
 struct nmi_desc {
 	raw_spinlock_t lock;
@@ -514,12 +516,14 @@ do_nmi(struct pt_regs *regs, long error_code)
 #endif
 
 	nmi_enter();
+	trace_nmi_entry(2);
 
 	inc_irq_stat(__nmi_count);
 
 	if (!ignore_nmis)
 		default_do_nmi(regs);
 
+	trace_nmi_exit(2);
 	nmi_exit();
 
 #ifdef CONFIG_X86_64
-- 
2.19.0

Re: [PATCH V2 1/2] trace,x86: Add external_interrupts to the irq_vectors class

[Thomas Gleixner]

On Mon, 1 Apr 2019, Daniel Bristot de Oliveira wrote:

> Currently, the irq_vectors is showing the entry and exit events for
> the interrupts of the architecture, but not for external interrupts.

Those are covered by the irq tracepoints. Is there a really good reason why
we need both?

Thanks,

	tglx

Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Thomas Gleixner]

On Mon, 1 Apr 2019, Daniel Bristot de Oliveira wrote:
> Currently, the irq_vector class of tracepoints does not include the NMI
> entry. The NMI was in the first set of tracepoints for IRQs, but it was
> dropped off because of the logic of switching IDT when enabling trace[1].
> However, as the switching IDT logic was removed [2], it is possible to add

Well, not really. tracepoints inside of do_nmi() have been there for a long
time.

The nasty part was that the irq_vector patches injected the tracepoints way
down in the low level entry code, which caused more problems than it solved
including the extra IDT switcheroo.

> the NMI tracepoints back.

So again we have two tracepoints. One for the entry and one for the
handlers. Do we really need both? If so please provide some rationale.

> The tracepoints looks like:
>           <idle>-0     [000] d.Z.   179.594315: nmi_entry: vector=2
>           <idle>-0     [000] d.Z.   179.594396: nmi_exit: vector=2
> 
> [1] trace,x86: irq vector tracepoint support
>     https://lwn.net/Articles/555465/

Please use https://lkml.kernel.org/r/$MESSAGE-ID

> [2] commit 4b9a8dca0e58 ("x86/idt: Remove the tracing IDT completely")
> 
> Changes from V1:
>   - Fix a compilation problem when CONFIG_X86_LOCAL_APIC is not set (kbuild test)

Please put changes below the '---' separator. They are not part of the
final changelog and having them below spares the maintainer the time to
remove them manually.

Thanks,

	tglx

Re: [PATCH V2 1/2] trace,x86: Add external_interrupts to the irq_vectors class

[Daniel Bristot de Oliveira]

On 4/5/19 11:15 PM, Thomas Gleixner wrote:
> On Mon, 1 Apr 2019, Daniel Bristot de Oliveira wrote:
> 
>> Currently, the irq_vectors is showing the entry and exit events for
>> the interrupts of the architecture, but not for external interrupts.
> 
> Those are covered by the irq tracepoints. Is there a really good reason why
> we need both?

The irq_handler_* tracepoints might give the "imprecise" idea that more than one
interrupts were raised when we have shared handlers. For instance:

------------ %< ----------------
f-892   [000] d.h.   790.617251: external_interrupt_entry: vector=37
f-892   [000] d.h.   790.617257: irq_handler_entry: irq=11 name=uhci_hcd:usb3
f-892   [000] d.h.   790.617343: irq_handler_exit: irq=11 ret=handled
f-892   [000] d.h.   790.617343: irq_handler_entry: irq=11 name=uhci_hcd:usb4
f-892   [000] d.h.   790.617349: irq_handler_exit: irq=11 ret=unhandled
f-892   [000] d.h.   790.617350: irq_handler_entry: irq=11 name=qxl
f-892   [000] d.h.   790.617360: irq_handler_exit: irq=11 ret=handled
f-892   [000] d.h.   790.617387: external_interrupt_exit: vector=37
------------ >% ----------------

In this case, a single interrupt occurrence (vector 37) caused two handlers to
handle their interrupt.

From a latency analysis perspective, the external_interrupt_* tracepoints turn
clearer that a single interrupt interfered in the thread execution happened, not
two separated executions of the same vector.

The outer-most tracepoints also help to have a more precise accounting of the
interference:

Using the sum of the irq_handler_* tracepoints we have:
(790.617343−790.617257)+(790.617349−790.617343)+(790.617360−790.617350) = 102 us

While using the irq_vector based one:
 790.617387-790.617251 = 136 us

So, the proposed tracepoints help clarify the logical sequence of the interrupt
handling, while increasing the precision of the measurements.

Thoughts?

-- Daniel
> Thanks,
> 
> 	tglx
> 

Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Daniel Bristot de Oliveira]

On 4/5/19 11:50 PM, Thomas Gleixner wrote:
> On Mon, 1 Apr 2019, Daniel Bristot de Oliveira wrote:
>> Currently, the irq_vector class of tracepoints does not include the NMI
>> entry. The NMI was in the first set of tracepoints for IRQs, but it was
>> dropped off because of the logic of switching IDT when enabling trace[1].
>> However, as the switching IDT logic was removed [2], it is possible to add
> 
> Well, not really. tracepoints inside of do_nmi() have been there for a long
> time.
> 
> The nasty part was that the irq_vector patches injected the tracepoints way
> down in the low level entry code, which caused more problems than it solved
> including the extra IDT switcheroo.

humm... the benefits of having the tracepoints at the very begin/end of the
handler is that it captures better the amount of interference/overhead it caused
in the current thread (and IRQ too in the case of NMIs).

>> the NMI tracepoints back.
> 
> So again we have two tracepoints. One for the entry and one for the
> handlers. Do we really need both? If so please provide some rationale.

For example:

  f-4447  [000] d.Z.  1253.162036: nmi_entry: vector=2
  f-4447  [000] d.Z.  1253.162038: nmi_handler: nmi_cpu_backtrace_handler()
delta_ns: 354 handled: 0
  f-4447  [000] d.Z.  1253.162267: nmi_exit: vector=2

The nmi_handler tracepoint points to an interference of 354 ns, what is very
good! But the difference of time between the two irq_vectors tracepoint is:

  1253.162267-1253.162036 = 231 us!

The number looks really odd, but tracing with function tracer, we see this:

Thread running:
  f-4447  [000] d.Z.  1487.689288: rcu_nmi_enter <-do_nmi
  f-4447  [000] d.Z.  1487.689289: rcu_dynticks_curr_cpu_in_eqs <-rcu_nmi_enter

NMI starts:
  f-4447  [000] d.Z.  1487.689290: nmi_entry: vector=2
  f-4447  [000] d.Z.  1487.689291: default_do_nmi <-do_nmi
  f-4447  [000] d.Z.  1487.689291: nmi_handle <-default_do_nmi
  f-4447  [000] d.Z.  1487.689291: nmi_cpu_backtrace_handler <-nmi_handle

It handles very fast:
  f-4447  [000] d.Z.  1487.689292: nmi_handler: nmi_cpu_backtrace_handler()
delta_ns: 780 handled: 0

But some other functions continues running in the NMI context:
[Dazed and confused, but trying to continue message ]
  f-4447  [000] d.Z.  1487.689292: _raw_spin_trylock <-default_do_nmi
  f-4447  [000] d.Z.  1487.689566: unknown_nmi_error <-default_do_nmi
  f-4447  [000] d.Z.  1487.689566: nmi_handle <-unknown_nmi_error
  f-4447  [000] d.Z.  1487.689567: printk <-unknown_nmi_error
  f-4447  [000] d.Z.  1487.689567: vprintk_func <-printk
  f-4447  [000] d.Z.  1487.689567: printk_safe_log_store <-vprintk_func
  f-4447  [000] d.Z.  1487.689569: arch_irq_work_raise <-irq_work_queue
  f-4447  [000] d.Z.  1487.689569: default_send_IPI_self <-arch_irq_work_raise
  f-4447  [000] d.Z.  1487.689569: __default_send_IPI_shortcut
<-default_send_IPI_self
  f-4447  [000] d.Z.  1487.689585: native_apic_wait_icr_idle <-arch_irq_work_raise
  f-4447  [000] d.Z.  1487.689588: printk <-unknown_nmi_error
  f-4447  [000] d.Z.  1487.689588: vprintk_func <-printk
  f-4447  [000] d.Z.  1487.689588: printk_safe_log_store <-vprintk_func
  f-4447  [000] d.Z.  1487.689588: printk <-unknown_nmi_error.cold.13
  f-4447  [000] d.Z.  1487.689588: vprintk_func <-printk
  f-4447  [000] d.Z.  1487.689588: printk_safe_log_store <-vprintk_func

Handler finishes:
  f-4447  [000] d.Z.  1487.689589: nmi_exit: vector=2
  f-4447  [000] d.Z.  1487.689589: rcu_nmi_exit <-do_nmi
  f-4447  [000] d.Z.  1487.689589: rcu_irq_exit <-rcu_nmi_exit

And it was actually also (potentially) delaying an timer:
  f-4447  [000] d...  1487.689590: smp_irq_work_interrupt <-irq_work_interrupt

So, the nmi_handle tracepoint would not make suspicious that the NMI caused the
delay, but the irq_vectors would (because of their position).

Finally, we would have to enable a single class of tracepoints to monitor all
interrupts.

PS: I am using the vanilla kernel in a vm, so the numbers are higher, but still,
they have the same scale in the bare metal.

Thoughts?

-- Daniel

>> The tracepoints looks like:
>>           <idle>-0     [000] d.Z.   179.594315: nmi_entry: vector=2
>>           <idle>-0     [000] d.Z.   179.594396: nmi_exit: vector=2
>>
>> [1] trace,x86: irq vector tracepoint support
>>     https://lwn.net/Articles/555465/
> 
> Please use https://lkml.kernel.org/r/$MESSAGE-ID
> 
>> [2] commit 4b9a8dca0e58 ("x86/idt: Remove the tracing IDT completely")
>>
>> Changes from V1:
>>   - Fix a compilation problem when CONFIG_X86_LOCAL_APIC is not set (kbuild test)
> 
> Please put changes below the '---' separator. They are not part of the
> final changelog and having them below spares the maintainer the time to
> remove them manually.
> 
> Thanks,
> 
> 	tglx
> 

Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Steven Rostedt]

On Mon, 8 Apr 2019 14:24:47 +0200
Daniel Bristot de Oliveira <bristot@redhat.com> wrote:

> NMI starts:
>   f-4447  [000] d.Z.  1487.689290: nmi_entry: vector=2
>   f-4447  [000] d.Z.  1487.689291: default_do_nmi <-do_nmi
>   f-4447  [000] d.Z.  1487.689291: nmi_handle <-default_do_nmi
>   f-4447  [000] d.Z.  1487.689291: nmi_cpu_backtrace_handler <-nmi_handle
> 
> It handles very fast:
>   f-4447  [000] d.Z.  1487.689292: nmi_handler: nmi_cpu_backtrace_handler()
> delta_ns: 780 handled: 0
> 
> But some other functions continues running in the NMI context:
> [Dazed and confused, but trying to continue message ]
>   f-4447  [000] d.Z.  1487.689292: _raw_spin_trylock <-default_do_nmi
>   f-4447  [000] d.Z.  1487.689566: unknown_nmi_error <-default_do_nmi
>   f-4447  [000] d.Z.  1487.689566: nmi_handle <-unknown_nmi_error
>   f-4447  [000] d.Z.  1487.689567: printk <-unknown_nmi_error
>   f-4447  [000] d.Z.  1487.689567: vprintk_func <-printk
>   f-4447  [000] d.Z.  1487.689567: printk_safe_log_store <-vprintk_func
>   f-4447  [000] d.Z.  1487.689569: arch_irq_work_raise <-irq_work_queue
>   f-4447  [000] d.Z.  1487.689569: default_send_IPI_self <-arch_irq_work_raise
>   f-4447  [000] d.Z.  1487.689569: __default_send_IPI_shortcut
> <-default_send_IPI_self

Just to remove confusion. Your example is to show that the new
tracepoints would have shown that the NMI was long due to the printk? As
running printk from NMI (even with the delayed output) isn't a normal
path.

-- Steve

Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Daniel Bristot de Oliveira]

On 4/8/19 3:46 PM, Steven Rostedt wrote:
> On Mon, 8 Apr 2019 14:24:47 +0200
> Daniel Bristot de Oliveira <bristot@redhat.com> wrote:
> 
>> NMI starts:
>>   f-4447  [000] d.Z.  1487.689290: nmi_entry: vector=2
>>   f-4447  [000] d.Z.  1487.689291: default_do_nmi <-do_nmi
>>   f-4447  [000] d.Z.  1487.689291: nmi_handle <-default_do_nmi
>>   f-4447  [000] d.Z.  1487.689291: nmi_cpu_backtrace_handler <-nmi_handle
>>
>> It handles very fast:
>>   f-4447  [000] d.Z.  1487.689292: nmi_handler: nmi_cpu_backtrace_handler()
>> delta_ns: 780 handled: 0
>>
>> But some other functions continues running in the NMI context:
>> [Dazed and confused, but trying to continue message ]
>>   f-4447  [000] d.Z.  1487.689292: _raw_spin_trylock <-default_do_nmi
>>   f-4447  [000] d.Z.  1487.689566: unknown_nmi_error <-default_do_nmi
>>   f-4447  [000] d.Z.  1487.689566: nmi_handle <-unknown_nmi_error
>>   f-4447  [000] d.Z.  1487.689567: printk <-unknown_nmi_error
>>   f-4447  [000] d.Z.  1487.689567: vprintk_func <-printk
>>   f-4447  [000] d.Z.  1487.689567: printk_safe_log_store <-vprintk_func
>>   f-4447  [000] d.Z.  1487.689569: arch_irq_work_raise <-irq_work_queue
>>   f-4447  [000] d.Z.  1487.689569: default_send_IPI_self <-arch_irq_work_raise
>>   f-4447  [000] d.Z.  1487.689569: __default_send_IPI_shortcut
>> <-default_send_IPI_self
> 
> Just to remove confusion. Your example is to show that the new
> tracepoints would have shown that the NMI was long due to the printk? As
> running printk from NMI (even with the delayed output) isn't a normal
> path.

The example is "to show that the new tracepoints would have shown that the NMI
was longer than what the existing tracepoint pointed." The example was not the
best, I agree.. but... it serves to illustrate the idea.

-- Daniel

Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Steven Rostedt]

On Mon, 8 Apr 2019 15:57:07 +0200
Daniel Bristot de Oliveira <bristot@redhat.com> wrote:

> > Just to remove confusion. Your example is to show that the new
> > tracepoints would have shown that the NMI was long due to the printk? As
> > running printk from NMI (even with the delayed output) isn't a normal
> > path.  
> 
> The example is "to show that the new tracepoints would have shown that the NMI
> was longer than what the existing tracepoint pointed." The example was not the
> best, I agree.. but... it serves to illustrate the idea.

Sure, just wanted to verify that was your intent.

Thanks,

-- Steve