linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* RE: [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
@ 2012-09-12  0:00 Seiji Aguchi
  2012-09-12  4:18 ` H. Peter Anvin
  0 siblings, 1 reply; 4+ messages in thread
From: Seiji Aguchi @ 2012-09-12  0:00 UTC (permalink / raw)
  To: Thomas Gleixner (tglx@linutronix.de)
  Cc: linux-kernel, rostedt, 'mingo@elte.hu' (mingo@elte.hu),
	x86, dle-develop, Satoru Moriya

Thomas,

Please review my patch as we talked in Plumbers.

Seiji

> -----Original Message-----
> From: Seiji Aguchi
> Sent: Friday, August 24, 2012 11:22 AM
> To: Thomas Gleixner (tglx@linutronix.de)
> Cc: linux-kernel@vger.kernel.org; rostedt@goodmis.org; 'mingo@elte.hu' (mingo@elte.hu); x86@kernel.org; dle-
> develop@lists.sourceforge.net; Satoru Moriya
> Subject: [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
> 
> Tomas,
> 
> It is helpful if you can review this patch.
> 
> Change log
>  v2 -> v3
>  - Remove an invalidate_tlb_vector event because it was replaced by a call function vector
>    in a following commit.
>    http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commit;h=52aec3308db85f4e9f5c8b9f5dc4fbd0138c6fa4
> 
>  v1 -> v2
>  - Modify variable name from irq to vector.
>  - Merge arch-specific tracepoints below to an arch_irq_vector_entry/exit.
>    - error_apic_vector
>    - thermal_apic_vector
>    - threshold_apic_vector
>    - spurious_apic_vector
>    - x86_platform_ipi_vector
> 
> As Vaibhav explained in the thread below, tracepoints for irq vectors are useful.
> 
> http://www.spinics.net/lists/mm-commits/msg85707.html
> 
> <snip>
> 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.
> <snip>
> 
> On the other hand, my usecase is tracing just local timer event and getting a value of instruction pointer.
> 
>   I suggested to add an argument local timer event to get instruction pointer before.
>   But there is another way to get it with external module like systemtap.
>   So, I don't need to add any argument to irq vector tracepoints now.
> 
> Vaibhav's patch shared a trace point ,irq_vector_entry/irq_vector_exit, in all events.
> But there is an above use case to trace specific irq_vector rather than tracing all events.
> In this case, we are concerned about overhead due to unwanted events.
> 
> This patch modifies Vaibhav's one as follows.
>  - Separate generic, and across-architecture tracepoints to enable independently.
>    - nmi_vector
>    - local_timer_vector
>    - reschedule_vector
>    - call_function_vector
>    - call_function_single_vector
>    - irq_work_entry_vector
> 
>  - Rename architecture-specific tracepoints from irq_vector_entry/exit to
>    arch_irq_vector_entry/exit.
>    - error_apic_vector
>    - thermal_apic_vector
>    - threshold_apic_vector
>    - spurious_apic_vector
>    - x86_platform_ipi_vector
> 
>    Those x86 specific ones are not really frequently raised vectors, so
>    enabling them all won't affect performance and readability of the
>    traces too much.
> 
>  Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
> 
> ---
>  arch/x86/include/asm/irq_vectors.h       |    9 ++
>  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                    |    5 +
>  arch/x86/kernel/irq_work.c               |    3 +
>  arch/x86/kernel/nmi.c                    |    3 +
>  arch/x86/kernel/smp.c                    |    7 +
>  include/trace/events/irq_vectors.h       |  209 ++++++++++++++++++++++++++++++
>  9 files changed, 249 insertions(+), 0 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 1508e51..510ced5 100644
> --- a/arch/x86/include/asm/irq_vectors.h
> +++ b/arch/x86/include/asm/irq_vectors.h
> @@ -158,4 +158,13 @@ static inline int invalid_vm86_irq(int irq)
>  # define NR_IRQS			NR_IRQS_LEGACY
>  #endif
> 
> +#define irq_vector_name(vector) { vector, #vector }
> +
> +#define irq_vector_name_table						\
> +			irq_vector_name(ERROR_APIC_VECTOR),		\
> +			irq_vector_name(THERMAL_APIC_VECTOR),		\
> +			irq_vector_name(THRESHOLD_APIC_VECTOR),		\
> +			irq_vector_name(SPURIOUS_APIC_VECTOR),		\
> +			irq_vector_name(X86_PLATFORM_IPI_VECTOR)
> +
>  #endif /* _ASM_X86_IRQ_VECTORS_H */
> diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c index 24deb30..b9cdd8f 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/irq_remapping.h>
>  #include <asm/perf_event.h>
> @@ -895,7 +896,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
>  	 */
>  	irq_enter();
>  	exit_idle();
> +	trace_local_timer_entry(LOCAL_TIMER_VECTOR);
>  	local_apic_timer_interrupt();
> +	trace_local_timer_exit(LOCAL_TIMER_VECTOR);
>  	irq_exit();
> 
>  	set_irq_regs(old_regs);
> @@ -1881,6 +1884,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
> 
>  	irq_enter();
>  	exit_idle();
> +	trace_arch_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...
> @@ -1895,6 +1899,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_arch_irq_vector_exit(SPURIOUS_APIC_VECTOR);
>  	irq_exit();
>  }
> 
> @@ -1918,6 +1923,7 @@ void smp_error_interrupt(struct pt_regs *regs)
> 
>  	irq_enter();
>  	exit_idle();
> +	trace_arch_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);
> @@ -1938,6 +1944,7 @@ void smp_error_interrupt(struct pt_regs *regs)
> 
>  	apic_printk(APIC_DEBUG, KERN_CONT "\n");
> 
> +	trace_arch_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 47a1870..63c2cc8 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/apic.h>
> @@ -382,8 +383,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)  {
>  	irq_enter();
>  	exit_idle();
> +	trace_arch_irq_vector_entry(THERMAL_APIC_VECTOR);
>  	inc_irq_stat(irq_thermal_count);
>  	smp_thermal_vector();
> +	trace_arch_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 aa578ca..de74768 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)  {
>  	irq_enter();
>  	exit_idle();
> +	trace_arch_irq_vector_entry(THRESHOLD_APIC_VECTOR);
>  	inc_irq_stat(irq_threshold_count);
>  	mce_threshold_vector();
> +	trace_arch_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 1f5f1d5..f4d7344 100644
> --- a/arch/x86/kernel/irq.c
> +++ b/arch/x86/kernel/irq.c
> @@ -18,6 +18,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 */ @@ -218,11 +221,13 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
> 
>  	exit_idle();
> 
> +	trace_arch_irq_vector_entry(X86_PLATFORM_IPI_VECTOR);
>  	inc_irq_stat(x86_platform_ipis);
> 
>  	if (x86_platform_ipi_callback)
>  		x86_platform_ipi_callback();
> 
> +	trace_arch_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..2cf7505 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_work_entry(IRQ_WORK_VECTOR);
>  	inc_irq_stat(apic_irq_work_irqs);
>  	irq_work_run();
> +	trace_irq_work_exit(IRQ_WORK_VECTOR);
>  	irq_exit();
>  }
> 
> diff --git a/arch/x86/kernel/nmi.c b/arch/x86/kernel/nmi.c index f84f5c5..cc57aba 100644
> --- a/arch/x86/kernel/nmi.c
> +++ b/arch/x86/kernel/nmi.c
> @@ -28,6 +28,7 @@
>  #include <asm/mach_traps.h>
>  #include <asm/nmi.h>
>  #include <asm/x86_init.h>
> +#include <trace/events/irq_vectors.h>
> 
>  struct nmi_desc {
>  	spinlock_t lock;
> @@ -482,12 +483,14 @@ do_nmi(struct pt_regs *regs, long error_code)
>  	nmi_nesting_preprocess(regs);
> 
>  	nmi_enter();
> +	trace_nmi_entry(NMI_VECTOR);
> 
>  	inc_irq_stat(__nmi_count);
> 
>  	if (!ignore_nmis)
>  		default_do_nmi(regs);
> 
> +	trace_nmi_exit(NMI_VECTOR);
>  	nmi_exit();
> 
>  	/* On i386, may loop back to preprocess */ diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c index
> 48d2b7d..5b2d6de 100644
> --- a/arch/x86/kernel/smp.c
> +++ b/arch/x86/kernel/smp.c
> @@ -23,6 +23,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>
> @@ -252,8 +253,10 @@ finish:
>  void smp_reschedule_interrupt(struct pt_regs *regs)  {
>  	ack_APIC_irq();
> +	trace_reschedule_entry(RESCHEDULE_VECTOR);
>  	inc_irq_stat(irq_resched_count);
>  	scheduler_ipi();
> +	trace_reschedule_exit(RESCHEDULE_VECTOR);
>  	/*
>  	 * KVM uses this interrupt to force a cpu out of guest mode
>  	 */
> @@ -263,8 +266,10 @@ void smp_call_function_interrupt(struct pt_regs *regs)  {
>  	ack_APIC_irq();
>  	irq_enter();
> +	trace_call_function_entry(CALL_FUNCTION_VECTOR);
>  	generic_smp_call_function_interrupt();
>  	inc_irq_stat(irq_call_count);
> +	trace_call_function_exit(CALL_FUNCTION_VECTOR);
>  	irq_exit();
>  }
> 
> @@ -272,8 +277,10 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)  {
>  	ack_APIC_irq();
>  	irq_enter();
> +	trace_call_function_single_entry(CALL_FUNCTION_SINGLE_VECTOR);
>  	generic_smp_call_function_single_interrupt();
>  	inc_irq_stat(irq_call_count);
> +	trace_call_function_single_exit(CALL_FUNCTION_SINGLE_VECTOR);
>  	irq_exit();
>  }
> 
> diff --git a/include/trace/events/irq_vectors.h b/include/trace/events/irq_vectors.h
> new file mode 100644
> index 0000000..fffe0c0
> --- /dev/null
> +++ b/include/trace/events/irq_vectors.h
> @@ -0,0 +1,209 @@
> +#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
> +
> +
> +/*
> + * This class is used by generic ,cross-architecture tracepoints.
> + */
> +DECLARE_EVENT_CLASS(irq_vector,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector),
> +
> +	TP_STRUCT__entry(
> +		__field(	int,	vector	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->vector = vector;
> +	),
> +
> +	TP_printk("vector=%d", __entry->vector) );
> +
> +/*
> + * nmi_entry - called before enterring a nmi vector handler  */
> +DEFINE_EVENT(irq_vector, nmi_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * nmi_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, nmi_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * local_timer_entry - called before enterring a local timer interrupt
> + * vector handler
> + */
> +DEFINE_EVENT(irq_vector, local_timer_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * local_timer_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, local_timer_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * reschedule_entry - called before enterring a reschedule vector
> +handler  */ DEFINE_EVENT(irq_vector, reschedule_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * reschedule_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, reschedule_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * call_function_entry - called before enterring a call function
> + *			 vector handler
> + */
> +DEFINE_EVENT(irq_vector, call_function_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * call_function_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, call_function_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * call_function_single_entry - called before enterring a call function
> + * single vector handler
> + */
> +DEFINE_EVENT(irq_vector, call_function_single_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * call_function_single_exit - called immediately after the interrupt
> +vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, call_function_single_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * irq_work_entry - called before enterring an irq work vector handler
> +*/ DEFINE_EVENT(irq_vector, irq_work_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * irq_work_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(irq_vector, irq_work_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * This class is used by arch-specific tracepoints.
> + */
> +DECLARE_EVENT_CLASS(arch_irq_vector,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector),
> +
> +	TP_STRUCT__entry(
> +		__field(	int,	vector	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->vector = vector;
> +	),
> +
> +	TP_printk("vector=%d name=%s", __entry->vector,
> +		__print_symbolic(__entry->vector, irq_vector_name_table)) );
> +
> +/*
> + * arch_irq_vector_entry - called before enterring a interrupt vector
> +handler  */ DEFINE_EVENT(arch_irq_vector, arch_irq_vector_entry,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +/*
> + * arch_irq_vector_exit - called immediately after the interrupt vector
> + * handler returns
> + */
> +DEFINE_EVENT(arch_irq_vector, arch_irq_vector_exit,
> +
> +	TP_PROTO(int vector),
> +
> +	TP_ARGS(vector)
> +);
> +
> +#endif /*  _TRACE_IRQ_VECTORS_H */
> +
> +/* This part must be outside protection */ #include
> +<trace/define_trace.h>
> -- 1.7.1

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
  2012-09-12  0:00 [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints Seiji Aguchi
@ 2012-09-12  4:18 ` H. Peter Anvin
  2012-09-12 13:37   ` Seiji Aguchi
  0 siblings, 1 reply; 4+ messages in thread
From: H. Peter Anvin @ 2012-09-12  4:18 UTC (permalink / raw)
  To: Seiji Aguchi
  Cc: Thomas Gleixner (tglx@linutronix.de),
	linux-kernel, rostedt, 'mingo@elte.hu' (mingo@elte.hu),
	x86, dle-develop, Satoru Moriya

On 09/11/2012 05:00 PM, Seiji Aguchi wrote:
> Thomas,
>
> Please review my patch as we talked in Plumbers.
>

Is there any measurable latency added here?  These are some of the most 
performance- (or at least latency-)critical paths in the kernel.

	-hpa

-- 
H. Peter Anvin, Intel Open Source Technology Center
I work for Intel.  I don't speak on their behalf.


^ permalink raw reply	[flat|nested] 4+ messages in thread

* RE: [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
  2012-09-12  4:18 ` H. Peter Anvin
@ 2012-09-12 13:37   ` Seiji Aguchi
  0 siblings, 0 replies; 4+ messages in thread
From: Seiji Aguchi @ 2012-09-12 13:37 UTC (permalink / raw)
  To: H. Peter Anvin
  Cc: Thomas Gleixner (tglx@linutronix.de),
	linux-kernel, rostedt, 'mingo@elte.hu' (mingo@elte.hu),
	x86, dle-develop, Satoru Moriya

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 1031 bytes --]

Hi,

I will submit some performance testing result.

Thanks!

Seiji

> -----Original Message-----
> From: H. Peter Anvin [mailto:hpa@zytor.com]
> Sent: Wednesday, September 12, 2012 12:18 AM
> To: Seiji Aguchi
> Cc: Thomas Gleixner (tglx@linutronix.de); linux-kernel@vger.kernel.org; rostedt@goodmis.org; 'mingo@elte.hu' (mingo@elte.hu);
> x86@kernel.org; dle-develop@lists.sourceforge.net; Satoru Moriya
> Subject: Re: [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
> 
> On 09/11/2012 05:00 PM, Seiji Aguchi wrote:
> > Thomas,
> >
> > Please review my patch as we talked in Plumbers.
> >
> 
> Is there any measurable latency added here?  These are some of the most
> performance- (or at least latency-)critical paths in the kernel.
> 
> 	-hpa
> 
> --
> H. Peter Anvin, Intel Open Source Technology Center I work for Intel.  I don't speak on their behalf.

ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

^ permalink raw reply	[flat|nested] 4+ messages in thread

* [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints
@ 2012-08-24 15:21 Seiji Aguchi
  0 siblings, 0 replies; 4+ messages in thread
From: Seiji Aguchi @ 2012-08-24 15:21 UTC (permalink / raw)
  To: Thomas Gleixner (tglx@linutronix.de)
  Cc: linux-kernel, rostedt, 'mingo@elte.hu' (mingo@elte.hu),
	x86, dle-develop, Satoru Moriya

Tomas,

It is helpful if you can review this patch.

Change log
 v2 -> v3
 - Remove an invalidate_tlb_vector event because it was replaced by a call function vector
   in a following commit.
   http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commit;h=52aec3308db85f4e9f5c8b9f5dc4fbd0138c6fa4

 v1 -> v2
 - Modify variable name from irq to vector.
 - Merge arch-specific tracepoints below to an arch_irq_vector_entry/exit.
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

As Vaibhav explained in the thread below, tracepoints for irq vectors are useful.

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

<snip>
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.
<snip>

On the other hand, my usecase is tracing just local timer event and getting a value of instruction pointer.

  I suggested to add an argument local timer event to get instruction pointer before.
  But there is another way to get it with external module like systemtap.
  So, I don't need to add any argument to irq vector tracepoints now.

Vaibhav's patch shared a trace point ,irq_vector_entry/irq_vector_exit, in all events.
But there is an above use case to trace specific irq_vector rather than tracing all events.
In this case, we are concerned about overhead due to unwanted events.

This patch modifies Vaibhav's one as follows.
 - Separate generic, and across-architecture tracepoints to enable independently.
   - nmi_vector
   - local_timer_vector
   - reschedule_vector
   - call_function_vector
   - call_function_single_vector 
   - irq_work_entry_vector

 - Rename architecture-specific tracepoints from irq_vector_entry/exit to 
   arch_irq_vector_entry/exit.
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

   Those x86 specific ones are not really frequently raised vectors, so
   enabling them all won't affect performance and readability of the
   traces too much.

 Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>

---
 arch/x86/include/asm/irq_vectors.h       |    9 ++
 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                    |    5 +
 arch/x86/kernel/irq_work.c               |    3 +
 arch/x86/kernel/nmi.c                    |    3 +
 arch/x86/kernel/smp.c                    |    7 +
 include/trace/events/irq_vectors.h       |  209 ++++++++++++++++++++++++++++++
 9 files changed, 249 insertions(+), 0 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 1508e51..510ced5 100644
--- a/arch/x86/include/asm/irq_vectors.h
+++ b/arch/x86/include/asm/irq_vectors.h
@@ -158,4 +158,13 @@ static inline int invalid_vm86_irq(int irq)
 # define NR_IRQS			NR_IRQS_LEGACY
 #endif
 
+#define irq_vector_name(vector) { vector, #vector }
+
+#define irq_vector_name_table						\
+			irq_vector_name(ERROR_APIC_VECTOR),		\
+			irq_vector_name(THERMAL_APIC_VECTOR),		\
+			irq_vector_name(THRESHOLD_APIC_VECTOR),		\
+			irq_vector_name(SPURIOUS_APIC_VECTOR),		\
+			irq_vector_name(X86_PLATFORM_IPI_VECTOR)
+
 #endif /* _ASM_X86_IRQ_VECTORS_H */
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c index 24deb30..b9cdd8f 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/irq_remapping.h>
 #include <asm/perf_event.h>
@@ -895,7 +896,9 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
 	 */
 	irq_enter();
 	exit_idle();
+	trace_local_timer_entry(LOCAL_TIMER_VECTOR);
 	local_apic_timer_interrupt();
+	trace_local_timer_exit(LOCAL_TIMER_VECTOR);
 	irq_exit();
 
 	set_irq_regs(old_regs);
@@ -1881,6 +1884,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 
 	irq_enter();
 	exit_idle();
+	trace_arch_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...
@@ -1895,6 +1899,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_arch_irq_vector_exit(SPURIOUS_APIC_VECTOR);
 	irq_exit();
 }
 
@@ -1918,6 +1923,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	irq_enter();
 	exit_idle();
+	trace_arch_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);
@@ -1938,6 +1944,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	apic_printk(APIC_DEBUG, KERN_CONT "\n");
 
+	trace_arch_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 47a1870..63c2cc8 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/apic.h>
@@ -382,8 +383,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)  {
 	irq_enter();
 	exit_idle();
+	trace_arch_irq_vector_entry(THERMAL_APIC_VECTOR);
 	inc_irq_stat(irq_thermal_count);
 	smp_thermal_vector();
+	trace_arch_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 aa578ca..de74768 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)  {
 	irq_enter();
 	exit_idle();
+	trace_arch_irq_vector_entry(THRESHOLD_APIC_VECTOR);
 	inc_irq_stat(irq_threshold_count);
 	mce_threshold_vector();
+	trace_arch_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 1f5f1d5..f4d7344 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -18,6 +18,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 */ @@ -218,11 +221,13 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
 
 	exit_idle();
 
+	trace_arch_irq_vector_entry(X86_PLATFORM_IPI_VECTOR);
 	inc_irq_stat(x86_platform_ipis);
 
 	if (x86_platform_ipi_callback)
 		x86_platform_ipi_callback();
 
+	trace_arch_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..2cf7505 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_work_entry(IRQ_WORK_VECTOR);
 	inc_irq_stat(apic_irq_work_irqs);
 	irq_work_run();
+	trace_irq_work_exit(IRQ_WORK_VECTOR);
 	irq_exit();
 }
 
diff --git a/arch/x86/kernel/nmi.c b/arch/x86/kernel/nmi.c index f84f5c5..cc57aba 100644
--- a/arch/x86/kernel/nmi.c
+++ b/arch/x86/kernel/nmi.c
@@ -28,6 +28,7 @@
 #include <asm/mach_traps.h>
 #include <asm/nmi.h>
 #include <asm/x86_init.h>
+#include <trace/events/irq_vectors.h>
 
 struct nmi_desc {
 	spinlock_t lock;
@@ -482,12 +483,14 @@ do_nmi(struct pt_regs *regs, long error_code)
 	nmi_nesting_preprocess(regs);
 
 	nmi_enter();
+	trace_nmi_entry(NMI_VECTOR);
 
 	inc_irq_stat(__nmi_count);
 
 	if (!ignore_nmis)
 		default_do_nmi(regs);
 
+	trace_nmi_exit(NMI_VECTOR);
 	nmi_exit();
 
 	/* On i386, may loop back to preprocess */ diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c index 48d2b7d..5b2d6de 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -23,6 +23,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>
@@ -252,8 +253,10 @@ finish:
 void smp_reschedule_interrupt(struct pt_regs *regs)  {
 	ack_APIC_irq();
+	trace_reschedule_entry(RESCHEDULE_VECTOR);
 	inc_irq_stat(irq_resched_count);
 	scheduler_ipi();
+	trace_reschedule_exit(RESCHEDULE_VECTOR);
 	/*
 	 * KVM uses this interrupt to force a cpu out of guest mode
 	 */
@@ -263,8 +266,10 @@ void smp_call_function_interrupt(struct pt_regs *regs)  {
 	ack_APIC_irq();
 	irq_enter();
+	trace_call_function_entry(CALL_FUNCTION_VECTOR);
 	generic_smp_call_function_interrupt();
 	inc_irq_stat(irq_call_count);
+	trace_call_function_exit(CALL_FUNCTION_VECTOR);
 	irq_exit();
 }
 
@@ -272,8 +277,10 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)  {
 	ack_APIC_irq();
 	irq_enter();
+	trace_call_function_single_entry(CALL_FUNCTION_SINGLE_VECTOR);
 	generic_smp_call_function_single_interrupt();
 	inc_irq_stat(irq_call_count);
+	trace_call_function_single_exit(CALL_FUNCTION_SINGLE_VECTOR);
 	irq_exit();
 }
 
diff --git a/include/trace/events/irq_vectors.h b/include/trace/events/irq_vectors.h
new file mode 100644
index 0000000..fffe0c0
--- /dev/null
+++ b/include/trace/events/irq_vectors.h
@@ -0,0 +1,209 @@
+#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
+
+
+/*
+ * This class is used by generic ,cross-architecture tracepoints.
+ */
+DECLARE_EVENT_CLASS(irq_vector,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector),
+
+	TP_STRUCT__entry(
+		__field(	int,	vector	)
+	),
+
+	TP_fast_assign(
+		__entry->vector = vector;
+	),
+
+	TP_printk("vector=%d", __entry->vector) );
+
+/*
+ * nmi_entry - called before enterring a nmi vector handler  */ 
+DEFINE_EVENT(irq_vector, nmi_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * nmi_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, nmi_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * local_timer_entry - called before enterring a local timer interrupt
+ * vector handler
+ */
+DEFINE_EVENT(irq_vector, local_timer_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * local_timer_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, local_timer_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * reschedule_entry - called before enterring a reschedule vector 
+handler  */ DEFINE_EVENT(irq_vector, reschedule_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * reschedule_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, reschedule_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * call_function_entry - called before enterring a call function
+ *			 vector handler
+ */
+DEFINE_EVENT(irq_vector, call_function_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * call_function_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, call_function_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * call_function_single_entry - called before enterring a call function
+ * single vector handler
+ */
+DEFINE_EVENT(irq_vector, call_function_single_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * call_function_single_exit - called immediately after the interrupt 
+vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, call_function_single_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * irq_work_entry - called before enterring an irq work vector handler  
+*/ DEFINE_EVENT(irq_vector, irq_work_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * irq_work_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(irq_vector, irq_work_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * This class is used by arch-specific tracepoints.
+ */
+DECLARE_EVENT_CLASS(arch_irq_vector,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector),
+
+	TP_STRUCT__entry(
+		__field(	int,	vector	)
+	),
+
+	TP_fast_assign(
+		__entry->vector = vector;
+	),
+
+	TP_printk("vector=%d name=%s", __entry->vector,
+		__print_symbolic(__entry->vector, irq_vector_name_table)) );
+
+/*
+ * arch_irq_vector_entry - called before enterring a interrupt vector 
+handler  */ DEFINE_EVENT(arch_irq_vector, arch_irq_vector_entry,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+/*
+ * arch_irq_vector_exit - called immediately after the interrupt vector
+ * handler returns
+ */
+DEFINE_EVENT(arch_irq_vector, arch_irq_vector_exit,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector)
+);
+
+#endif /*  _TRACE_IRQ_VECTORS_H */
+
+/* This part must be outside protection */ #include 
+<trace/define_trace.h>
-- 1.7.1

^ permalink raw reply related	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2012-09-12 13:38 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2012-09-12  0:00 [Resend][PATCH V3] trace,x86: add x86 irq vector tracepoints Seiji Aguchi
2012-09-12  4:18 ` H. Peter Anvin
2012-09-12 13:37   ` Seiji Aguchi
  -- strict thread matches above, loose matches on Subject: below --
2012-08-24 15:21 Seiji Aguchi

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).