Re: [PATCH] new irq tracer

[Mathieu Desnoyers]

* Jason Baron (jbaron@xxxxxxxxxx) wrote:
> hi,
> 
> Using a copule of tracepoints i've implemented an 'irq tracer' which has
> the following column format:
> 
> [time][irq][action][handled][cpu][length]
> 
> for example on my system:
> 
> [ 1038.927248381]     28     eth0      1        3     0.000002745
> [ 1038.927544688]     28     eth0      1        3     0.000002520
> [ 1038.927593609]     28     eth0      1        3     0.000002509
> [ 1038.974087675]     29     ahci      1        1     0.000013135
> [ 1038.974288475]     29     ahci      1        1     0.000005542
> [ 1038.974414324]     29     ahci      1        1     0.000007953
> 
> I think this patch is useful in understanding irq system behavior, and
> for tracking down irq driver handlers that are firing too often or
> spending too much time handling an irq. This approach could be extended
> to the timer irq and for softirqs...
> 
> thanks,
> 

Hi Jason,

If you are in the process of rewriting the LTTng instrumentation from
scratch, please have a look at the git tree first, at least as an
inspiration source, otherwise we will end up tring to merge two subtily
different sets of instrumentation into the mainline.

Please see :

http://git.kernel.org/?p=linux/kernel/git/compudj/linux-2.6-lttng.git

Thanks,

Mathieu

> -Jason
> 
> Signed-off-by: Jason Baron <jbaron@xxxxxxxxxx>
> 
> 
> ---
> 
>  include/trace/irq.h      |   24 +++++++
>  kernel/irq/handle.c      |    6 ++
>  kernel/trace/Kconfig     |    7 ++
>  kernel/trace/Makefile    |    1 
>  kernel/trace/trace.h     |    8 ++
>  kernel/trace/trace_irq.c |  151 ++++++++++++++++++++++++++++++++++++++++++++++
>  6 files changed, 197 insertions(+), 0 deletions(-)
>  create mode 100644 include/trace/irq.h
>  create mode 100644 kernel/trace/trace_irq.c
> 
> 
> diff --git a/include/trace/irq.h b/include/trace/irq.h
> new file mode 100644
> index 0000000..e4669c2
> --- /dev/null
> +++ b/include/trace/irq.h
> @@ -0,0 +1,24 @@
> +#ifndef _TRACE_IRQ_H
> +#define _TRACE_IRQ_H
> +
> +#include <linux/interrupt.h>
> +#include <linux/tracepoint.h>
> +
> +struct irq_trace {
> +	int retval;
> +	int irq;
> +	const char *name;
> +	int cpu;
> +	int handled;
> +	struct timespec duration;
> +	struct timespec start_time;
> +};
> +
> +DECLARE_TRACE(irq_entry,
> +	TPPROTO(unsigned int id),
> +	TPARGS(id));
> +DECLARE_TRACE(irq_exit,
> +	TPPROTO(unsigned int id, irqreturn_t retval),
> +	TPARGS(id, retval));
> +
> +#endif /* _TRACE_IRQ_H */
> diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
> index fdff380..34053b5 100644
> --- a/kernel/irq/handle.c
> +++ b/kernel/irq/handle.c
> @@ -18,6 +18,7 @@
>  #include <linux/rculist.h>
>  #include <linux/hash.h>
>  #include <linux/bootmem.h>
> +#include <trace/irq.h>
>  
>  #include "internals.h"
>  
> @@ -338,6 +339,9 @@ irqreturn_t no_action(int cpl, void *dev_id)
>  	return IRQ_NONE;
>  }
>  
> +DEFINE_TRACE(irq_entry);
> +DEFINE_TRACE(irq_exit);
> +
>  /**
>   * handle_IRQ_event - irq action chain handler
>   * @irq:	the interrupt number
> @@ -354,7 +358,9 @@ irqreturn_t handle_IRQ_event(unsigned int irq, struct irqaction *action)
>  		local_irq_enable_in_hardirq();
>  
>  	do {
> +		trace_irq_entry(irq);
>  		ret = action->handler(irq, action->dev_id);
> +		trace_irq_exit(irq, ret);
>  		if (ret == IRQ_HANDLED)
>  			status |= action->flags;
>  		retval |= ret;
> diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
> index 620f9cd..f62165c 100644
> --- a/kernel/trace/Kconfig
> +++ b/kernel/trace/Kconfig
> @@ -239,6 +239,13 @@ config POWER_TRACER
>  	  power management decisions, specifically the C-state and P-state
>  	  behavior.
>  
> +config IRQ_TRACER
> +	bool "Trace irq latencies"
> +	depends on DEBUG_KERNEL
> +	depends on X86
> +	select TRACING
> +	help
> +	  This tracer helps developers anaylze irq latencies.
>  
>  config STACK_TRACER
>  	bool "Trace max stack"
> diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> index 627090b..58b9f7e 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -38,5 +38,6 @@ obj-$(CONFIG_POWER_TRACER) += trace_power.o
>  obj-$(CONFIG_KMEMTRACE) += kmemtrace.o
>  obj-$(CONFIG_WORKQUEUE_TRACER) += trace_workqueue.o
>  obj-$(CONFIG_BLK_DEV_IO_TRACE)	+= blktrace.o
> +obj-$(CONFIG_IRQ_TRACER) += trace_irq.o
>  
>  libftrace-y := ftrace.o
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index dbff020..6a34aaa 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -11,6 +11,7 @@
>  #include <trace/boot.h>
>  #include <trace/kmemtrace.h>
>  #include <trace/power.h>
> +#include <trace/irq.h>
>  
>  enum trace_type {
>  	__TRACE_FIRST_TYPE = 0,
> @@ -33,6 +34,7 @@ enum trace_type {
>  	TRACE_KMEM_ALLOC,
>  	TRACE_KMEM_FREE,
>  	TRACE_POWER,
> +	TRACE_IRQ,
>  	TRACE_BLK,
>  
>  	__TRACE_LAST_TYPE,
> @@ -173,6 +175,11 @@ struct trace_power {
>  	struct power_trace	state_data;
>  };
>  
> +struct trace_irq {
> +	struct trace_entry	ent;
> +	struct irq_trace	irq_data;
> +};
> +
>  struct kmemtrace_alloc_entry {
>  	struct trace_entry	ent;
>  	enum kmemtrace_type_id type_id;
> @@ -298,6 +305,7 @@ extern void __ftrace_bad_type(void);
>  			  TRACE_GRAPH_RET);		\
>  		IF_ASSIGN(var, ent, struct hw_branch_entry, TRACE_HW_BRANCHES);\
>   		IF_ASSIGN(var, ent, struct trace_power, TRACE_POWER); \
> +		IF_ASSIGN(var, ent, struct trace_irq, TRACE_IRQ);	\
>  		IF_ASSIGN(var, ent, struct kmemtrace_alloc_entry,	\
>  			  TRACE_KMEM_ALLOC);	\
>  		IF_ASSIGN(var, ent, struct kmemtrace_free_entry,	\
> diff --git a/kernel/trace/trace_irq.c b/kernel/trace/trace_irq.c
> new file mode 100644
> index 0000000..1808316
> --- /dev/null
> +++ b/kernel/trace/trace_irq.c
> @@ -0,0 +1,151 @@
> +/*
> + * Copyright (C) 2009 Red Hat, Inc., Jason Baron <jbaron@xxxxxxxxxx>
> + */
> +
> +#include <linux/init.h>
> +#include <linux/debugfs.h>
> +#include <trace/irq.h>
> +#include <linux/kallsyms.h>
> +#include <linux/module.h>
> +#include <linux/interrupt.h>
> +#include <linux/ktime.h>
> +
> +#include "trace.h"
> +#include "trace_output.h"
> +
> +static struct trace_array *irq_trace;
> +static int __read_mostly trace_irq_enabled;
> +static ktime_t start_times[NR_IRQS];
> +
> +static void probe_irq_entry(unsigned int irq)
> +{
> +	if (!trace_irq_enabled)
> +		return;
> +	start_times[irq] = ktime_get();
> +}
> +
> +static void probe_irq_exit(unsigned int irq, irqreturn_t retval)
> +{
> +	struct ring_buffer_event *event;
> +	struct trace_irq *entry;
> +	struct trace_array *tr = irq_trace;
> +	struct irq_desc *desc;
> +	ktime_t end_time;
> +
> +	if (!trace_irq_enabled)
> +		return;
> +	end_time = ktime_get();
> +	desc = irq_to_desc(irq);
> +	event = trace_buffer_lock_reserve(tr, TRACE_IRQ,
> +					  sizeof(*entry), 0, 0);
> +	if (!event)
> +		goto out;
> +	entry	= ring_buffer_event_data(event);
> +	entry->irq_data.retval = retval;
> +	entry->irq_data.name = desc->action->name;
> +	entry->irq_data.irq = irq;
> +	entry->irq_data.cpu = raw_smp_processor_id();
> +	if (retval == IRQ_HANDLED)
> +		entry->irq_data.handled = 1;
> +	else
> +		entry->irq_data.handled = 0;
> +	entry->irq_data.duration =
> +		ktime_to_timespec(ktime_sub(end_time, start_times[irq]));
> +	entry->irq_data.start_time = ktime_to_timespec(start_times[irq]);
> +	trace_buffer_unlock_commit(tr, event, 0, 0);
> + out:
> +	preempt_enable();
> +}
> +
> +static int tracing_irq_register(void)
> +{
> +	int ret;
> +
> +	ret = register_trace_irq_entry(probe_irq_entry);
> +	if (ret) {
> +		pr_info("irq trace: irq entry tracepoint failed to register\n");
> +		return ret;
> +	}
> +	ret = register_trace_irq_exit(probe_irq_exit);
> +	if (ret) {
> +		pr_info("irq trace: irq exit tracepoint failed to register\n");
> +		goto fail_exit;
> +	}
> +	return ret;
> +fail_exit:
> +	unregister_trace_irq_entry(probe_irq_entry);
> +	return ret;
> +}
> +
> +static void start_irq_trace(struct trace_array *tr)
> +{
> +	trace_irq_enabled = 1;
> +	tracing_irq_register();
> +}
> +
> +static void stop_irq_trace(struct trace_array *tr)
> +{
> +	trace_irq_enabled = 0;
> +	unregister_trace_irq_entry(probe_irq_entry);
> +	unregister_trace_irq_exit(probe_irq_exit);
> +}
> +
> +
> +static int irq_trace_init(struct trace_array *tr)
> +{
> +	int cpu;
> +	irq_trace = tr;
> +
> +	trace_irq_enabled = 1;
> +	tracing_irq_register();
> +	for_each_cpu(cpu, cpu_possible_mask)
> +		tracing_reset(tr, cpu);
> +	return 0;
> +}
> +
> +static enum print_line_t irq_print_line(struct trace_iterator *iter)
> +{
> +	int ret = 0;
> +	struct trace_entry *entry = iter->ent;
> +	struct trace_irq *field;
> +	struct irq_trace *it;
> +	struct trace_seq *s = &iter->seq;
> +
> +	trace_assign_type(field, entry);
> +	it = &field->irq_data;
> +	if (entry->type == TRACE_IRQ) {
> +		ret = trace_seq_printf(s, "[%5ld.%09ld]     %d     %s      %d        %d     %ld.%09ld\n",
> +					it->start_time.tv_sec,
> +					it->start_time.tv_nsec,
> +					it->irq, it->name, it->handled, it->cpu,
> +					it->duration.tv_sec,
> +					it->duration.tv_nsec);
> +		if (!ret)
> +			return TRACE_TYPE_PARTIAL_LINE;
> +		return TRACE_TYPE_HANDLED;
> +	}
> +	return TRACE_TYPE_UNHANDLED;
> +}
> +
> +static void irq_print_headers(struct seq_file *s)
> +{
> +	seq_printf(s, "      [time]         [irq] [action] [handled] [cpu] [length]\n");
> +	seq_printf(s, "         |             |      |        |        |       |   \n\n");
> +}
> +
> +static struct tracer irq_tracer __read_mostly =
> +{
> +	.name		= "irq",
> +	.init		= irq_trace_init,
> +	.start		= start_irq_trace,
> +	.stop		= stop_irq_trace,
> +	.reset		= stop_irq_trace,
> +	.print_header	= irq_print_headers,
> +	.print_line	= irq_print_line,
> +};
> +
> +static int init_irq_trace(void)
> +{
> +	return register_tracer(&irq_tracer);
> +}
> +device_initcall(init_irq_trace);
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
--
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/