[PATCH] trace: Add special x86 irq entry/exit tracepoints

From: Vaibhav Nagarnaik
Date: Mon Apr 25 2011 - 19:42:15 EST

From: Jiaying Zhang <jiayingz@xxxxxxxxxx>

Apart from the normal interrupts, we often also need to trace
architecture special interrupts. The following patch adds the event
definition and trace instrumentation for some x86 special interrupts. We
hope the similar approach can also be used to trace special interrupts
on other architectures. However, the patch only supports x86 at this
point.

With this patch, following 'special' interrupts are logged by ftrace
(when enabled):

Interrupt as in /proc/interrupts Name as it appears in ftrace log
NMI: Non-maskable interrupts : NMI_VECTOR
LOC: Local timer interrupts : LOCAL_TIMER_VECTOR
SPU: Spurious interrupts : SPURIOUS_APIC_VECTOR
PMI: Performance monitoring interrupts : <not added>
PND: Performance pending work : LOCAL_PENDING_VECTOR
RES: Rescheduling interrupts : RESCHEDULE_VECTOR
CAL: Function call interrupts : CALL_FUNCTION_VECTOR or
CALL_FUNCTION_SINGLE_VECTOR
TLB: TLB shootdowns : INVALIDATE_TLB_VECTOR_START to
INVALIDATE_TLB_VECTOR_END
TRM: Thermal event interrupts : THERMAL_APIC_VECTOR
THR: Threshold APIC interrupts : THRESHOLD_APIC_VECTOR
MCE: Machine check exceptions : <not added>
MCP: Machine check polls : <not added>
ERR: : ERROR_APIC_VECTOR
MIS: : <not added>
PLT: Platform interrupts : X86_PLATFORM_IPI_VECTOR

Enabled the added tracepoints and verified the output:
$ echo 1 > debug/tracing/events/irq/special_irq_entry/enable
$ echo 1 > debug/tracing/events/irq/special_irq_exit/enable
$ cat debug/tracing/trace | more
<idle>-0 [000] 263.699530: special_irq_entry: irq=239
name=LOCAL_TIMER_VECTOR tlb_vector=-1
<idle>-0 [003] 263.699700: special_irq_entry: irq=239
name=LOCAL_TIMER_VECTOR tlb_vector=-1
<idle>-0 [004] 263.699749: special_irq_entry: irq=237
name=INVALIDATE_TLB_VECTOR tlb_vector=30
<...>-9483 [000] 263.700498: special_irq_entry: irq=239
name=LOCAL_TIMER_VECTOR tlb_vector=-1
<idle>-0 [004] 263.700498: special_irq_entry: irq=239
name=LOCAL_TIMER_VECTOR tlb_vector=-1
<idle>-0 [003] 263.700519: special_irq_entry: irq=239
name=LOCAL_TIMER_VECTOR tlb_vector=-1

A custom script compares the two:
$ sh ~/ftrace_test.sh
tracing...
cpu0: overrun: 0
cpu1: overrun: 0
cpu2: overrun: 0
cpu3: overrun: 0
IRQ ftrace record counts (ignoring numeric irq=(0|1|4|5|7|9|10|24) )
2 irq=242 name=INVALIDATE_TLB_VECTOR_2
3 irq=252 name=CALL_FUNCTION_VECTOR
6 irq=241 name=INVALIDATE_TLB_VECTOR_1
6 irq=2 name=NMI_VECTOR
22 irq=240 name=INVALIDATE_TLB_VECTOR_0
40 irq=251 name=CALL_FUNCTION_SINGLE_VECTOR
587 irq=253 name=RESCHEDULE_VECTOR
15013 irq=239 name=LOCAL_TIMER_VECTOR
/proc/interrupts stats difference
6 NMI (Non-maskable interrupts)
14945 LOC (Local timer interrupts)
6 PMI (Performance monitoring interrupts)
578 RES (Rescheduling interrupts)
42 CAL (Function call interrupts)
30 TLB (TLB shootdowns)
4 MCP (Machine check polls)

In above output:
NMI (Non-maskable interrupts) == NMI_VECTOR (irq 2)
LOC (Local timer interrupts) == LOCAL_TIMER_VECTOR (irq 239)
RES (Rescheduling interrupts) == RESCHEDULE_VECTOR (irq=253)
CAL (Function call interrupts) == CALL_FUNCTION_VECTOR (irq 252) +
CALL_FUNCTION_SINGLE_VECTOR (irq 251)
TLB (TLB shootdowns) == INVALIDATE_TLB_VECTOR_0 (irq=240) +
INVALIDATE_TLB_VECTOR_1 (irq=241) +
INVALIDATE_TLB_VECTOR_2 (irq=242)

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@xxxxxxxxxx>
---
arch/x86/kernel/apic/apic.c | 7 +++
arch/x86/kernel/cpu/mcheck/therm_throt.c | 3 +
arch/x86/kernel/cpu/mcheck/threshold.c | 3 +
arch/x86/kernel/irq.c | 4 +-
arch/x86/kernel/irq_work.c | 4 ++
arch/x86/kernel/smp.c | 7 +++
arch/x86/kernel/time.c | 6 +++
arch/x86/kernel/traps.c | 3 +
arch/x86/mm/tlb.c | 3 +
include/trace/events/irq.h | 68 ++++++++++++++++++++++++++++++
10 files changed, 107 insertions(+), 1 deletions(-)

diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index fabf01e..e601c27 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -33,6 +33,7 @@
#include <linux/dmi.h>
#include <linux/smp.h>
#include <linux/mm.h>
+#include <trace/events/irq.h>

#include <asm/perf_event.h>
#include <asm/x86_init.h>
@@ -857,7 +858,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
*/
exit_idle();
irq_enter();
+ trace_special_irq_entry(LOCAL_TIMER_VECTOR);
local_apic_timer_interrupt();
+ trace_special_irq_exit(LOCAL_TIMER_VECTOR);
irq_exit();

set_irq_regs(old_regs);
@@ -1790,6 +1793,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)

exit_idle();
irq_enter();
+ trace_special_irq_entry(SPURIOUS_APIC_VECTOR);
/*
* Check if this really is a spurious interrupt and ACK it
* if it is a vectored one. Just in case...
@@ -1804,6 +1808,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
/* see sw-dev-man vol 3, chapter 7.4.13.5 */
pr_info("spurious APIC interrupt on CPU#%d, "
"should never happen.\n", smp_processor_id());
+ trace_special_irq_exit(SPURIOUS_APIC_VECTOR);
irq_exit();
}

@@ -1816,6 +1821,7 @@ void smp_error_interrupt(struct pt_regs *regs)

exit_idle();
irq_enter();
+ trace_special_irq_entry(ERROR_APIC_VECTOR);
/* First tickle the hardware, only then report what went on. -- REW */
v = apic_read(APIC_ESR);
apic_write(APIC_ESR, 0);
@@ -1836,6 +1842,7 @@ void smp_error_interrupt(struct pt_regs *regs)
*/
pr_debug("APIC error on CPU%d: %02x(%02x)\n",
smp_processor_id(), v , v1);
+ trace_special_irq_exit(ERROR_APIC_VECTOR);
irq_exit();
}

diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index 6f8c5e9..abdec08 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -23,6 +23,7 @@
#include <linux/init.h>
#include <linux/smp.h>
#include <linux/cpu.h>
+#include <trace/events/irq.h>

#include <asm/processor.h>
#include <asm/system.h>
@@ -402,8 +403,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
{
exit_idle();
irq_enter();
+ trace_special_irq_entry(THERMAL_APIC_VECTOR);
inc_irq_stat(irq_thermal_count);
smp_thermal_vector();
+ trace_special_irq_exit(THERMAL_APIC_VECTOR);
irq_exit();
/* Ack only at the end to avoid potential reentry */
ack_APIC_irq();
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index d746df2..1943d9e 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -3,6 +3,7 @@
*/
#include <linux/interrupt.h>
#include <linux/kernel.h>
+#include <trace/events/irq.h>

#include <asm/irq_vectors.h>
#include <asm/apic.h>
@@ -21,8 +22,10 @@ asmlinkage void smp_threshold_interrupt(void)
{
exit_idle();
irq_enter();
+ trace_special_irq_entry(THRESHOLD_APIC_VECTOR);
inc_irq_stat(irq_threshold_count);
mce_threshold_vector();
+ trace_special_irq_exit(THRESHOLD_APIC_VECTOR);
irq_exit();
/* Ack only at the end to avoid potential reentry */
ack_APIC_irq();
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index 1cb0b9f..6f857c5 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -8,6 +8,7 @@
#include <linux/seq_file.h>
#include <linux/smp.h>
#include <linux/ftrace.h>
+#include <trace/events/irq.h>
#include <linux/delay.h>

#include <asm/apic.h>
@@ -211,12 +212,13 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
exit_idle();

irq_enter();
-
+ trace_special_irq_entry(X86_PLATFORM_IPI_VECTOR);
inc_irq_stat(x86_platform_ipis);

if (x86_platform_ipi_callback)
x86_platform_ipi_callback();

+ trace_special_irq_exit(X86_PLATFORM_IPI_VECTOR);
irq_exit();

set_irq_regs(old_regs);
diff --git a/arch/x86/kernel/irq_work.c b/arch/x86/kernel/irq_work.c
index ca8f703..9ee00ba 100644
--- a/arch/x86/kernel/irq_work.c
+++ b/arch/x86/kernel/irq_work.c
@@ -8,13 +8,17 @@
#include <linux/irq_work.h>
#include <linux/hardirq.h>
#include <asm/apic.h>
+#include <asm/irq_vectors.h>
+#include <trace/events/irq.h>

void smp_irq_work_interrupt(struct pt_regs *regs)
{
irq_enter();
ack_APIC_irq();
+ trace_special_irq_entry(IRQ_WORK_VECTOR);
inc_irq_stat(apic_irq_work_irqs);
irq_work_run();
+ trace_special_irq_exit(IRQ_WORK_VECTOR);
irq_exit();
}

diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index 513deac..51ec1f8 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -22,6 +22,7 @@
#include <linux/interrupt.h>
#include <linux/cpu.h>
#include <linux/gfp.h>
+#include <trace/events/irq.h>

#include <asm/mtrr.h>
#include <asm/tlbflush.h>
@@ -201,7 +202,9 @@ static void native_stop_other_cpus(int wait)
void smp_reschedule_interrupt(struct pt_regs *regs)
{
ack_APIC_irq();
+ trace_special_irq_entry(RESCHEDULE_VECTOR);
inc_irq_stat(irq_resched_count);
+ trace_special_irq_exit(RESCHEDULE_VECTOR);
/*
* KVM uses this interrupt to force a cpu out of guest mode
*/
@@ -211,8 +214,10 @@ void smp_call_function_interrupt(struct pt_regs *regs)
{
ack_APIC_irq();
irq_enter();
+ trace_special_irq_entry(CALL_FUNCTION_VECTOR);
generic_smp_call_function_interrupt();
inc_irq_stat(irq_call_count);
+ trace_special_irq_exit(CALL_FUNCTION_VECTOR);
irq_exit();
}

@@ -220,8 +225,10 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)
{
ack_APIC_irq();
irq_enter();
+ trace_special_irq_entry(CALL_FUNCTION_SINGLE_VECTOR);
generic_smp_call_function_single_interrupt();
inc_irq_stat(irq_call_count);
+ trace_special_irq_exit(CALL_FUNCTION_SINGLE_VECTOR);
irq_exit();
}

diff --git a/arch/x86/kernel/time.c b/arch/x86/kernel/time.c
index 25a28a2..687b087 100644
--- a/arch/x86/kernel/time.c
+++ b/arch/x86/kernel/time.c
@@ -13,6 +13,7 @@
#include <linux/interrupt.h>
#include <linux/time.h>
#include <linux/mca.h>
+#include <trace/events/irq.h>

#include <asm/vsyscall.h>
#include <asm/x86_init.h>
@@ -26,6 +27,8 @@
volatile unsigned long __jiffies __section_jiffies = INITIAL_JIFFIES;
#endif

+static struct irqaction *irq0_action;
+
unsigned long profile_pc(struct pt_regs *regs)
{
unsigned long pc = instruction_pointer(regs);
@@ -59,7 +62,9 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
/* Keep nmi watchdog up to date */
inc_irq_stat(irq0_irqs);

+ trace_irq_handler_entry(0, irq0_action);
global_clock_event->event_handler(global_clock_event);
+ trace_irq_handler_exit(0, irq0_action, 1);

/* MCA bus quirk: Acknowledge irq0 by setting bit 7 in port 0x61 */
if (MCA_bus)
@@ -76,6 +81,7 @@ static struct irqaction irq0 = {

void __init setup_default_timer_irq(void)
{
+ irq0_action = &irq0;
setup_irq(0, &irq0);
}

diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index b9b6716..4857ff6 100644
--- a/arch/x86/kernel/traps.c
+++ b/arch/x86/kernel/traps.c
@@ -31,6 +31,7 @@
#include <linux/mm.h>
#include <linux/smp.h>
#include <linux/io.h>
+#include <trace/events/irq.h>

#ifdef CONFIG_EISA
#include <linux/ioport.h>
@@ -434,12 +435,14 @@ dotraplinkage notrace __kprobes void
do_nmi(struct pt_regs *regs, long error_code)
{
nmi_enter();
+ trace_special_irq_entry(NMI_VECTOR);

inc_irq_stat(__nmi_count);

if (!ignore_nmis)
default_do_nmi(regs);

+ trace_special_irq_exit(NMI_VECTOR);
nmi_exit();
}

diff --git a/arch/x86/mm/tlb.c b/arch/x86/mm/tlb.c
index d6c0418..f119306 100644
--- a/arch/x86/mm/tlb.c
+++ b/arch/x86/mm/tlb.c
@@ -5,6 +5,7 @@
#include <linux/smp.h>
#include <linux/interrupt.h>
#include <linux/module.h>
+#include <trace/events/irq.h>
#include <linux/cpu.h>

#include <asm/tlbflush.h>
@@ -141,6 +142,7 @@ void smp_invalidate_interrupt(struct pt_regs *regs)
sender = ~regs->orig_ax - INVALIDATE_TLB_VECTOR_START;
f = &flush_state[sender];

+ trace_special_irq_entry(INVALIDATE_TLB_VECTOR_START + sender);
if (!cpumask_test_cpu(cpu, to_cpumask(f->flush_cpumask)))
goto out;
/*
@@ -167,6 +169,7 @@ out:
cpumask_clear_cpu(cpu, to_cpumask(f->flush_cpumask));
smp_mb__after_clear_bit();
inc_irq_stat(irq_tlb_count);
+ trace_special_irq_exit(INVALIDATE_TLB_VECTOR_START + sender);
}

static void flush_tlb_others_ipi(const struct cpumask *cpumask,
diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 4b4c7d9..6c0af78 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -139,6 +139,74 @@ DEFINE_EVENT(softirq, softirq_raise,
TP_ARGS(vec_nr)
);

+#ifdef CONFIG_X86
+#include <asm/irq_vectors.h>
+
+#define special_irq_name(sirq) { sirq, #sirq }
+#define show_special_irq_name(val) \
+ __print_symbolic(val, \
+ special_irq_name(NMI_VECTOR), \
+ special_irq_name(LOCAL_TIMER_VECTOR), \
+ special_irq_name(ERROR_APIC_VECTOR), \
+ special_irq_name(RESCHEDULE_VECTOR), \
+ special_irq_name(CALL_FUNCTION_VECTOR), \
+ special_irq_name(CALL_FUNCTION_SINGLE_VECTOR), \
+ special_irq_name(THERMAL_APIC_VECTOR), \
+ special_irq_name(THRESHOLD_APIC_VECTOR), \
+ special_irq_name(REBOOT_VECTOR), \
+ special_irq_name(SPURIOUS_APIC_VECTOR), \
+ special_irq_name(IRQ_WORK_VECTOR), \
+ special_irq_name(X86_PLATFORM_IPI_VECTOR) \
+ )
+
+#define IS_INVALIDATE_TLB_VECTOR(__irq) (\
+ __irq >= INVALIDATE_TLB_VECTOR_START && \
+ __irq <= INVALIDATE_TLB_VECTOR_END)
+
+DECLARE_EVENT_CLASS(special_irq,
+
+ TP_PROTO(int irq),
+
+ TP_ARGS(irq),
+
+ TP_STRUCT__entry(
+ __field( int, irq )
+ ),
+
+ TP_fast_assign(
+ __entry->irq = irq;
+ ),
+
+ TP_printk("irq=%d name=%s tlb_vector=%d", __entry->irq,
+ IS_INVALIDATE_TLB_VECTOR(__entry->irq) ?
+ "INVALIDATE_TLB_VECTOR" : show_special_irq_name(__entry->irq),
+ IS_INVALIDATE_TLB_VECTOR(__entry->irq) ?
+ __entry->irq - INVALIDATE_TLB_VECTOR_START : -1)
+);
+
+/*
+ * special_irq_entry - called before enterring a special interrupt
+ * such as apic timer, spurious interrupt, and etc.
+ */
+DEFINE_EVENT(special_irq, special_irq_entry,
+
+ TP_PROTO(int irq),
+
+ TP_ARGS(irq)
+);
+
+/*
+ * special_irq_exit - called immediately after the special interrupt
+ * handler returns
+ */
+DEFINE_EVENT(special_irq, special_irq_exit,
+
+ TP_PROTO(int irq),
+
+ TP_ARGS(irq)
+);
+#endif /* CONFIG_X86 */
+
#endif /* _TRACE_IRQ_H */

/* This part must be outside protection */
--
1.7.3.1

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/