[PATCH 0/2] Add tracepoints to trace all x86 system IRQs

[PATCH 0/2] Add tracepoints to trace all x86 system IRQs

[Vaibhav Nagarnaik]

This is a patch series aiming to trace all the x86 system IRQs. The
tracepoints make it easier to understand IRQ interaction with other
system events and how do the IRQs affect the system behavior.

Patch#0 adds irq_handler_{entry,exit} tracepoints to x86 timer interrupt
handler.
Patch#1 creates a irq_vectors/ event sub system and
irq_vectors_{entry,exit} trace events. It adds tracepoints to all x86
IRQ vector handlers.

Currently the patch only adds tracepoints to x86. A similar approach can
be taken with other architectures to trace IRQ vectors in the system.

Previous iterations of this patch set:
https://lkml.org/lkml/2011/4/22/321
https://lkml.org/lkml/2011/7/14/309


Vaibhav Nagarnaik (2):
  trace,x86: Add tracepoint to x86 timer interrupt handler
  trace,x86: Add x86 irq vector entry/exit tracepoints

 arch/x86/include/asm/irq_vectors.h       |   50 ++++++++++++++++++++++++++
 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                    |    6 +++-
 arch/x86/kernel/irq_work.c               |    3 ++
 arch/x86/kernel/smp.c                    |    7 ++++
 arch/x86/kernel/time.c                   |   15 +++++---
 arch/x86/kernel/traps.c                  |    3 ++
 arch/x86/mm/tlb.c                        |    3 ++
 include/trace/events/irq_vectors.h       |   56 ++++++++++++++++++++++++++++++
 11 files changed, 149 insertions(+), 7 deletions(-)
 create mode 100644 include/trace/events/irq_vectors.h

-- 
1.7.3.1

[PATCH 1/2] trace,x86: Add tracepoint to x86 timer interrupt handler

[Vaibhav Nagarnaik]

The x86 timer interrupt handler is the only handler not traced in the
irq/irq_handler_{entry|exit} trace events.

Add tracepoints to the interrupt handler to trace it.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/kernel/time.c |   15 +++++++++------
 1 files changed, 9 insertions(+), 6 deletions(-)

diff --git a/arch/x86/kernel/time.c b/arch/x86/kernel/time.c
index 5a64d05..74d2280 100644
--- a/arch/x86/kernel/time.c
+++ b/arch/x86/kernel/time.c
@@ -51,6 +51,13 @@ unsigned long profile_pc(struct pt_regs *regs)
 }
 EXPORT_SYMBOL(profile_pc);
 
+static irqreturn_t timer_interrupt(int irq, void *dev_id);
+static struct irqaction irq0  = {
+	.handler = timer_interrupt,
+	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
+	.name = "timer"
+};
+
 /*
  * Default timer interrupt handler for PIT/HPET
  */
@@ -59,7 +66,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(irq, &irq0);
 	global_clock_event->event_handler(global_clock_event);
+	trace_irq_handler_exit(irq, &irq0, 1);
 
 	/* MCA bus quirk: Acknowledge irq0 by setting bit 7 in port 0x61 */
 	if (MCA_bus)
@@ -68,12 +77,6 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
 	return IRQ_HANDLED;
 }
 
-static struct irqaction irq0  = {
-	.handler = timer_interrupt,
-	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
-	.name = "timer"
-};
-
 void __init setup_default_timer_irq(void)
 {
 	setup_irq(0, &irq0);
-- 
1.7.3.1

Re: [PATCH 1/2] trace,x86: Add tracepoint to x86 timer interrupt handler

[Thomas Gleixner]

On Fri, 29 Jul 2011, Vaibhav Nagarnaik wrote:

> The x86 timer interrupt handler is the only handler not traced in the
> irq/irq_handler_{entry|exit} trace events.

Nonsense. The timer irq (irq0) comes via the genirq interrupt handling
and not via a special vector. So it's traced already.
 
Thanks,

	tglx

Re: [PATCH 1/2] trace,x86: Add tracepoint to x86 timer interrupt handler

[Vaibhav Nagarnaik]

On Wed, Sep 21, 2011 at 2:01 AM, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Fri, 29 Jul 2011, Vaibhav Nagarnaik wrote:
>
>> The x86 timer interrupt handler is the only handler not traced in the
>> irq/irq_handler_{entry|exit} trace events.
>
> Nonsense. The timer irq (irq0) comes via the genirq interrupt handling
> and not via a special vector. So it's traced already.
>

Thanks for pointing it out, I confused the PIT/HPET for the local timer
vector.

Could you also take a look at the patches that add tracing for traps?
https://lkml.org/lkml/2011/5/3/455
https://lkml.org/lkml/2011/5/3/456



Vaibhav Nagarnaik

[PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Vaibhav Nagarnaik]

The current interrupt traces from irq_handler_entry and irq_handler_exit
provide when an interrupt is handled. They provide good data about when
the system has switched to kernel space and how it affects the currently
running processes.

There are some IRQ vectors which trigger the system into kernel space,
which are not handled in generic IRQ handlers. Tracing such events gives
us the information about IRQ interaction with other system events.

The trace also tells where the system is spending its time. We want to
know which cores are handling interrupts and how they are affecting
other processes in the system. Also, the trace provides information
about when the cores are idle and which interrupts are changing that
state.

The following patch adds the event definition and trace instrumentation
for interrupt vectors. For x86, a lookup table is provided to print out
readable IRQ vector names. The template can be used to provide interrupt
vector lookup tables on other architectures.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/include/asm/irq_vectors.h       |   50 ++++++++++++++++++++++++++
 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                    |    6 +++-
 arch/x86/kernel/irq_work.c               |    3 ++
 arch/x86/kernel/smp.c                    |    7 ++++
 arch/x86/kernel/traps.c                  |    3 ++
 arch/x86/mm/tlb.c                        |    3 ++
 include/trace/events/irq_vectors.h       |   56 ++++++++++++++++++++++++++++++
 10 files changed, 140 insertions(+), 1 deletions(-)
 create mode 100644 include/trace/events/irq_vectors.h

diff --git a/arch/x86/include/asm/irq_vectors.h b/arch/x86/include/asm/irq_vectors.h
index f9a3209..386b69e 100644
--- a/arch/x86/include/asm/irq_vectors.h
+++ b/arch/x86/include/asm/irq_vectors.h
@@ -181,4 +181,54 @@ static inline int invalid_vm86_irq(int irq)
 # define NR_IRQS			NR_IRQS_LEGACY
 #endif
 
+#define irq_vector_name(sirq) { sirq, #sirq }
+#define invalidate_tlb_vector_name(i) { INVALIDATE_TLB_VECTOR_END-31+i, \
+					"INVALIDATE_TLB_VECTOR" }
+
+#define irq_vector_name_table						\
+			irq_vector_name(NMI_VECTOR),			\
+			irq_vector_name(LOCAL_TIMER_VECTOR),		\
+			irq_vector_name(ERROR_APIC_VECTOR),		\
+			irq_vector_name(RESCHEDULE_VECTOR),		\
+			irq_vector_name(CALL_FUNCTION_VECTOR),		\
+			irq_vector_name(CALL_FUNCTION_SINGLE_VECTOR),	\
+			irq_vector_name(THERMAL_APIC_VECTOR),		\
+			irq_vector_name(THRESHOLD_APIC_VECTOR),		\
+			irq_vector_name(REBOOT_VECTOR),			\
+			irq_vector_name(SPURIOUS_APIC_VECTOR),		\
+			irq_vector_name(IRQ_WORK_VECTOR),		\
+			irq_vector_name(X86_PLATFORM_IPI_VECTOR),	\
+			invalidate_tlb_vector_name(0),			\
+			invalidate_tlb_vector_name(1),			\
+			invalidate_tlb_vector_name(2),			\
+			invalidate_tlb_vector_name(3),			\
+			invalidate_tlb_vector_name(4),			\
+			invalidate_tlb_vector_name(5),			\
+			invalidate_tlb_vector_name(6),			\
+			invalidate_tlb_vector_name(7),			\
+			invalidate_tlb_vector_name(8),			\
+			invalidate_tlb_vector_name(9),			\
+			invalidate_tlb_vector_name(10),			\
+			invalidate_tlb_vector_name(11),			\
+			invalidate_tlb_vector_name(12),			\
+			invalidate_tlb_vector_name(13),			\
+			invalidate_tlb_vector_name(14),			\
+			invalidate_tlb_vector_name(15),			\
+			invalidate_tlb_vector_name(16),			\
+			invalidate_tlb_vector_name(17),			\
+			invalidate_tlb_vector_name(18),			\
+			invalidate_tlb_vector_name(19),			\
+			invalidate_tlb_vector_name(20),			\
+			invalidate_tlb_vector_name(21),			\
+			invalidate_tlb_vector_name(22),			\
+			invalidate_tlb_vector_name(23),			\
+			invalidate_tlb_vector_name(24),			\
+			invalidate_tlb_vector_name(25),			\
+			invalidate_tlb_vector_name(26),			\
+			invalidate_tlb_vector_name(27),			\
+			invalidate_tlb_vector_name(28),			\
+			invalidate_tlb_vector_name(29),			\
+			invalidate_tlb_vector_name(30),			\
+			invalidate_tlb_vector_name(31)
+
 #endif /* _ASM_X86_IRQ_VECTORS_H */
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 52fa563..0fe559f 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -34,6 +34,7 @@
 #include <linux/dmi.h>
 #include <linux/smp.h>
 #include <linux/mm.h>
+#include <trace/events/irq_vectors.h>
 
 #include <asm/perf_event.h>
 #include <asm/x86_init.h>
@@ -859,7 +860,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
 	 */
 	exit_idle();
 	irq_enter();
+	trace_irq_vector_entry(LOCAL_TIMER_VECTOR);
 	local_apic_timer_interrupt();
+	trace_irq_vector_exit(LOCAL_TIMER_VECTOR);
 	irq_exit();
 
 	set_irq_regs(old_regs);
@@ -1793,6 +1796,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_irq_vector_entry(SPURIOUS_APIC_VECTOR);
 	/*
 	 * Check if this really is a spurious interrupt and ACK it
 	 * if it is a vectored one.  Just in case...
@@ -1807,6 +1811,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_irq_vector_exit(SPURIOUS_APIC_VECTOR);
 	irq_exit();
 }
 
@@ -1830,6 +1835,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_irq_vector_entry(ERROR_APIC_VECTOR);
 	/* First tickle the hardware, only then report what went on. -- REW */
 	v0 = apic_read(APIC_ESR);
 	apic_write(APIC_ESR, 0);
@@ -1850,6 +1856,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	apic_printk(APIC_DEBUG, KERN_CONT "\n");
 
+	trace_irq_vector_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 27c6251..bd8fa96 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_vectors.h>
 
 #include <asm/processor.h>
 #include <asm/system.h>
@@ -398,8 +399,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
 {
 	exit_idle();
 	irq_enter();
+	trace_irq_vector_entry(THERMAL_APIC_VECTOR);
 	inc_irq_stat(irq_thermal_count);
 	smp_thermal_vector();
+	trace_irq_vector_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..ffde17b 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_vectors.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_irq_vector_entry(THRESHOLD_APIC_VECTOR);
 	inc_irq_stat(irq_threshold_count);
 	mce_threshold_vector();
+	trace_irq_vector_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 6c0802e..3e4696b 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -17,6 +17,9 @@
 #include <asm/mce.h>
 #include <asm/hw_irq.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/irq_vectors.h>
+
 atomic_t irq_err_count;
 
 /* Function pointer for generic interrupt vector handling */
@@ -211,12 +214,13 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
 	exit_idle();
 
 	irq_enter();
-
+	trace_irq_vector_entry(X86_PLATFORM_IPI_VECTOR);
 	inc_irq_stat(x86_platform_ipis);
 
 	if (x86_platform_ipi_callback)
 		x86_platform_ipi_callback();
 
+	trace_irq_vector_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..107754c 100644
--- a/arch/x86/kernel/irq_work.c
+++ b/arch/x86/kernel/irq_work.c
@@ -8,13 +8,16 @@
 #include <linux/irq_work.h>
 #include <linux/hardirq.h>
 #include <asm/apic.h>
+#include <trace/events/irq_vectors.h>
 
 void smp_irq_work_interrupt(struct pt_regs *regs)
 {
 	irq_enter();
 	ack_APIC_irq();
+	trace_irq_vector_entry(IRQ_WORK_VECTOR);
 	inc_irq_stat(apic_irq_work_irqs);
 	irq_work_run();
+	trace_irq_vector_exit(IRQ_WORK_VECTOR);
 	irq_exit();
 }
 
diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index 013e7eb..1b0ac99 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_vectors.h>
 
 #include <asm/mtrr.h>
 #include <asm/tlbflush.h>
@@ -199,8 +200,10 @@ static void native_stop_other_cpus(int wait)
 void smp_reschedule_interrupt(struct pt_regs *regs)
 {
 	ack_APIC_irq();
+	trace_irq_vector_entry(RESCHEDULE_VECTOR);
 	inc_irq_stat(irq_resched_count);
 	scheduler_ipi();
+	trace_irq_vector_exit(RESCHEDULE_VECTOR);
 	/*
 	 * KVM uses this interrupt to force a cpu out of guest mode
 	 */
@@ -210,8 +213,10 @@ void smp_call_function_interrupt(struct pt_regs *regs)
 {
 	ack_APIC_irq();
 	irq_enter();
+	trace_irq_vector_entry(CALL_FUNCTION_VECTOR);
 	generic_smp_call_function_interrupt();
 	inc_irq_stat(irq_call_count);
+	trace_irq_vector_exit(CALL_FUNCTION_VECTOR);
 	irq_exit();
 }
 
@@ -219,8 +224,10 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)
 {
 	ack_APIC_irq();
 	irq_enter();
+	trace_irq_vector_entry(CALL_FUNCTION_SINGLE_VECTOR);
 	generic_smp_call_function_single_interrupt();
 	inc_irq_stat(irq_call_count);
+	trace_irq_vector_exit(CALL_FUNCTION_SINGLE_VECTOR);
 	irq_exit();
 }
 
diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index bf4aa79..d22dd48 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_vectors.h>
 
 #define CREATE_TRACE_POINTS
 #include <trace/events/trap.h>
@@ -447,12 +448,14 @@ dotraplinkage notrace __kprobes void
 do_nmi(struct pt_regs *regs, long error_code)
 {
 	nmi_enter();
+	trace_irq_vector_entry(NMI_VECTOR);
 
 	inc_irq_stat(__nmi_count);
 
 	if (!ignore_nmis)
 		default_do_nmi(regs);
 
+	trace_irq_vector_exit(NMI_VECTOR);
 	nmi_exit();
 }
 
diff --git a/arch/x86/mm/tlb.c b/arch/x86/mm/tlb.c
index d6c0418..bf9475d 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_vectors.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_irq_vector_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_irq_vector_exit(INVALIDATE_TLB_VECTOR_START + sender);
 }
 
 static void flush_tlb_others_ipi(const struct cpumask *cpumask,
diff --git a/include/trace/events/irq_vectors.h b/include/trace/events/irq_vectors.h
new file mode 100644
index 0000000..699ddaa
--- /dev/null
+++ b/include/trace/events/irq_vectors.h
@@ -0,0 +1,56 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM irq_vectors
+
+#if !defined(_TRACE_IRQ_VECTORS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IRQ_VECTORS_H
+
+#include <linux/tracepoint.h>
+#include <asm/irq.h>
+
+#ifndef irq_vector_name_table
+#define irq_vector_name_table { -1, NULL }
+#endif
+
+DECLARE_EVENT_CLASS(irq_vector,
+
+	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", __entry->irq,
+		__print_symbolic(__entry->irq, irq_vector_name_table))
+);
+
+/*
+ * irq_vector_entry - called before enterring a interrupt vector handler
+ */
+DEFINE_EVENT(irq_vector, irq_vector_entry,
+
+	TP_PROTO(int irq),
+
+	TP_ARGS(irq)
+);
+
+/*
+ * irq_vector_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, irq_vector_exit,
+
+	TP_PROTO(int irq),
+
+	TP_ARGS(irq)
+);
+
+#endif /*  _TRACE_IRQ_VECTORS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
1.7.3.1

RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Seiji Aguchi]

Hi,

I'm interested in these tracepoints.
But this patch removed from -mm tree for some reason.

http://www.spinics.net/lists/mm-commits/msg85707.html

Do you plan to update it and push to upstream?

>@@ -859,7 +860,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
> 	 */
> 	exit_idle();
> 	irq_enter();
>+	trace_irq_vector_entry(LOCAL_TIMER_VECTOR);
> 	local_apic_timer_interrupt();
>+	trace_irq_vector_exit(LOCAL_TIMER_VECTOR);
> 	irq_exit();

It would be better if you add "regs" to the argument of trace_irq_vector_entry()/ trace_irq_vector_exit().

With "regs", we are able to know what part of the system CPUs execute periodically. 
This information really helps us find a root cause of system slowdown or hung up.

Seiji

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Frederic Weisbecker]

On Mon, Dec 12, 2011 at 04:52:18PM -0500, Seiji Aguchi wrote:
> Hi,
> 
> I'm interested in these tracepoints.
> But this patch removed from -mm tree for some reason.
> 
> http://www.spinics.net/lists/mm-commits/msg85707.html
> 
> Do you plan to update it and push to upstream?

Oh weird. Doesn't seem to be in -tip either. Anybody has
any clue about where this patch went?

> 
> >@@ -859,7 +860,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
> > 	 */
> > 	exit_idle();
> > 	irq_enter();
> >+	trace_irq_vector_entry(LOCAL_TIMER_VECTOR);
> > 	local_apic_timer_interrupt();
> >+	trace_irq_vector_exit(LOCAL_TIMER_VECTOR);
> > 	irq_exit();
> 
> It would be better if you add "regs" to the argument of trace_irq_vector_entry()/ trace_irq_vector_exit().
> 
> With "regs", we are able to know what part of the system CPUs execute periodically. 
> This information really helps us find a root cause of system slowdown or hung up.

What about using perf for that?

Just run:

	perf record -ag
	^C
	perf report

And you should find in the callchains some informations about where your CPUs
are spending time.

If you system is too slow for that but you're doing background tracing with
ftrace, you can use stacktrace with ftrace.

If it's hung up then we have the watchdog lockup detector.

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Mon, Dec 12, 2011 at 04:52:18PM -0500, Seiji Aguchi wrote:
> > Hi,
> > 
> > I'm interested in these tracepoints.
> > But this patch removed from -mm tree for some reason.
> > 
> > http://www.spinics.net/lists/mm-commits/msg85707.html
> > 
> > Do you plan to update it and push to upstream?
> 
> Oh weird. Doesn't seem to be in -tip either. Anybody has
> any clue about where this patch went?

Didn't Thomas critique them - if so then were those observations 
addressed?

Thanks,

	Ingo

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Frederic Weisbecker]

On Wed, Dec 14, 2011 at 09:18:09AM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > On Mon, Dec 12, 2011 at 04:52:18PM -0500, Seiji Aguchi wrote:
> > > Hi,
> > > 
> > > I'm interested in these tracepoints.
> > > But this patch removed from -mm tree for some reason.
> > > 
> > > http://www.spinics.net/lists/mm-commits/msg85707.html
> > > 
> > > Do you plan to update it and push to upstream?
> > 
> > Oh weird. Doesn't seem to be in -tip either. Anybody has
> > any clue about where this patch went?
> 
> Didn't Thomas critique them - if so then were those observations 
> addressed?
> 
> Thanks,
> 
> 	Ingo


Ah right. Vaibhav any news about that?

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Vaibhav Nagarnaik]

On Wed, Dec 14, 2011 at 6:47 AM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Wed, Dec 14, 2011 at 09:18:09AM +0100, Ingo Molnar wrote:
>> Didn't Thomas critique them - if so then were those observations
>> addressed?
>>
>> Thanks,
>>
>>       Ingo
>
>
> Ah right. Vaibhav any news about that?

Yes, the patches were dropped from -mm because of a merge conflict
with another patch. I am planning to resend the patch after rebasing
to the latest tip.

Thomas did critique them and I dropped a part of the patch. He didn't
comment on other parts, which I guess he didn't see any issues.



Vaibhav Nagarnaik

RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Seiji Aguchi]

Thank you for giving me a comment.
Unfortunately, neither "perf record" nor "ftrace" works for me.

>What about using perf for that?
>
>Just run:
>
>	perf record -ag
>	^C
>	perf report
>
>And you should find in the callchains some informations about where your CPUs
>are spending time.
>
>If you system is too slow for that 

When system is too slow, user command such as "perf record" may not work.

>but you're doing background tracing with
>ftrace, you can use stacktrace with ftrace.

Actually, We're doing background tracing in our customer's system rather than kernel debugging. 
Ftrace doesn't work for me because it checks the size of the stack at every function call.
Our customers are seriously concerned about its overhead.

For reducing the overhead, I need tracepoints so we can hook minimal function calls.

Seiji

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Frederic Weisbecker]

On Wed, Dec 14, 2011 at 10:09:11AM -0500, Seiji Aguchi wrote:
> Thank you for giving me a comment.
> Unfortunately, neither "perf record" nor "ftrace" works for me.
> 
> >What about using perf for that?
> >
> >Just run:
> >
> >	perf record -ag
> >	^C
> >	perf report
> >
> >And you should find in the callchains some informations about where your CPUs
> >are spending time.
> >
> >If you system is too slow for that 
> 
> When system is too slow, user command such as "perf record" may not work.
> 
> >but you're doing background tracing with
> >ftrace, you can use stacktrace with ftrace.
> 
> Actually, We're doing background tracing in our customer's system rather than kernel debugging. 
> Ftrace doesn't work for me because it checks the size of the stack at every function call.
> Our customers are seriously concerned about its overhead.
> 
> For reducing the overhead, I need tracepoints so we can hook minimal function calls.

Well ftrace is a whole subsystem that includes the function tracer and also an interface
for tracepoints in debugfs. I was rather suggesting the latter one. This is a good
choice for background tracing. And it supports stacktraces. If those generate too much
overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
if we can do that currently but this can be an interesting feature.

What are you using currently for the background tracing?

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Steven Rostedt]

On Wed, 2011-12-14 at 17:34 +0100, Frederic Weisbecker wrote:

> Well ftrace is a whole subsystem that includes the function tracer and also an interface
> for tracepoints in debugfs. 

Confusing isn't it ;)

> I was rather suggesting the latter one. This is a good
> choice for background tracing. And it supports stacktraces. If those generate too much
> overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
> if we can do that currently but this can be an interesting feature.

That would probably be trivial to add, especially now that we allow
pretty much a full stack trace anyway.

-- Steve

RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Seiji Aguchi]

>Well ftrace is a whole subsystem that includes the function tracer and also an interface
>for tracepoints in debugfs. I was rather suggesting the latter one. This is a good
>choice for background tracing. And it supports stacktraces. If those generate too much
>overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
>if we can do that currently but this can be an interesting feature.

I would like to periodically check which function call is executed
rather than seeing stacktrace.

AFAIK, purpose of stack tracing is showing where the biggest use of the stack takes place.
I don't think stack tracing achieves my goal.

Rip in local timer interrupt is more accurate information 
for achieving my goal than stacktrace

>
>What are you using currently for the background tracing?

Currently, we are using SystemTap in customer's system.
So, I would like to use this tracepoint with SystemTap.

RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Steven Rostedt]

On Wed, 2011-12-14 at 12:46 -0500, Seiji Aguchi wrote:
> >Well ftrace is a whole subsystem that includes the function tracer and also an interface
> >for tracepoints in debugfs. I was rather suggesting the latter one. This is a good
> >choice for background tracing. And it supports stacktraces. If those generate too much
> >overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
> >if we can do that currently but this can be an interesting feature.
> 
> I would like to periodically check which function call is executed
> rather than seeing stacktrace.
> 
> AFAIK, purpose of stack tracing is showing where the biggest use of the stack takes place.
> I don't think stack tracing achieves my goal.

You may be getting confused with /proc/sys/kernel/stack_tracer_enabled
and /debug/tracing/options/stacktrace
+ /debug/tracing/options/func_stack_trace

The "stack_tracer" is started via the proc file system and detects the
largest stack:

where doing echo 1 > /proc/sys/kernel/stack_tracer_enabled
gives you:

# cat /debug/tracing/stack_trace 
        Depth    Size   Location    (16 entries)
        -----    ----   --------
  0)     2976     416   find_busiest_group+0x6ff/0x7b6
  1)     2560     272   load_balance+0xa3/0x6c7
  2)     2288     144   __schedule+0x31a/0x6c5
  3)     2144      16   schedule+0x5a/0x5c
  4)     2128     160   schedule_timeout+0x37/0xf7
  5)     1968     112   wait_for_common+0xab/0x105
  6)     1856      16   wait_for_completion+0x1d/0x1f
  7)     1840     176   flush_work+0x46/0x60
  8)     1664      16   tty_flush_to_ldisc+0x15/0x17
  9)     1648      32   input_available_p+0x17/0x57
 10)     1616      48   n_tty_poll+0x6b/0x136
 11)     1568      64   tty_poll+0x64/0x7f
 12)     1504     880   do_select+0x327/0x519
 13)      624     400   core_sys_select+0x190/0x22f
 14)      224      96   sys_select+0x91/0xb9
 15)      128     128   system_call_fastpath+0x16/0x1b

But this is not what we are talking about. We are talking about either:

echo 1 > /debug/tracing/options/stacktrace
echo 1 > /debug/tracing/options/irq/irq_handler_entry
# tracer: nop
#
# entries-in-buffer/entries-written: 690/690   #P:2
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     rb_consumer-35    [001] d.h2   435.246779: irq_handler_entry: irq=21 name=uhci_hcd:usb4
     rb_consumer-35    [001] d.h2   435.246788: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.246789: irq_handler_entry: irq=21 name=eth0
     rb_consumer-35    [001] d.h2   435.246796: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.247027: irq_handler_entry: irq=21 name=uhci_hcd:usb4
     rb_consumer-35    [001] d.h2   435.247034: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.247035: irq_handler_entry: irq=21 name=eth0
     rb_consumer-35    [001] d.h2   435.247041: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper


(Note, the new header isn't pushed to mainline yet).

Or with function tracing:

echo do_irq > /debug/tracing/set_ftrace_filter
echo function > /debug/tracing/current_tracer
echo 1 > /debug/tracing/options/ftrace_stack_trace

# tracer: function
#
# entries-in-buffer/entries-written: 18/18   #P:2
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [001] d..1   609.407279: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407286: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.407527: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407532: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.407777: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407781: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.814166: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.814171: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
            sshd-2293  [001] d.s3   609.814416: do_IRQ <-ret_from_intr
            sshd-2293  [001] d.s3   609.814430: <stack trace>
 => ret_from_intr
 => _raw_spin_unlock_irqrestore
 => __queue_work
 => delayed_work_timer_fn
 => run_timer_softirq
 => __do_softirq
 => call_softirq
 => do_softirq
 => irq_exit
 => smp_apic_timer_interrupt
 => apic_timer_interrupt
 => _raw_spin_unlock_irqrestore
 => __wake_up
 => put_ldisc
 => tty_ldisc_deref
 => tty_poll
 => do_select
 => core_sys_select
 => sys_select
 => system_call_fastpath


Note, the above commands can be done easier if you download trace-cmd:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

The first operation is:

trace-cmd start -e irq_handler_entry -O stacktrace
# cat /sys/kernel/debug/tracing/trace

the second is:

trace-cmd start -p function -l do_IRQ --func-stack
# cat /sys/kernel/debug/tracing/trace


> 
> Rip in local timer interrupt is more accurate information 
> for achieving my goal than stacktrace

Does the above change your mind?

-- Steve

RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Seiji Aguchi]

Steven,

Thank you for giving me an explanation in detail how stacktrace works.
I was confused stacktrace.

>> Rip in local timer interrupt is more accurate information
>> for achieving my goal than stacktrace
>
>Does the above change your mind?



I'm concerned about amount of consumption of ring buffer because
I would like to use a background tracer for multiple cases in our costomer's system
for solving several issues.

As you know, I'm trying to improve tracepoints of signal events with others.
  https://lkml.org/lkml/2011/11/30/223
  
And I'm posting a patch of jbd2 event by myself.
  https://lkml.org/lkml/2011/11/29/328

How much does stacktrace consume ring buffer, compared to a tracepoint?

Seiji

Re: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Steven Rostedt]

On Wed, 2011-12-14 at 17:34 +0100, Frederic Weisbecker wrote:

> Well ftrace is a whole subsystem that includes the function tracer and also an interface
> for tracepoints in debugfs. I was rather suggesting the latter one. This is a good
> choice for background tracing. And it supports stacktraces. If those generate too much
> overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
> if we can do that currently but this can be an interesting feature.

Setting individual stack tracing does sound like a neat feature. Maybe
even determine a limit of how much to backtrace. Trace the full stack,
or just trace a given amount of frames.

This shouldn't be too hard to implement.

-- Steve