|
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [Xen-devel] [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing
More specifically:
- the handling of the TRC_HW_IRQ_HANDLED is fixed, both in
xentrace_format and in xenalyze;
- simple events for recording when we enter and exit the
do_IRQ function, as well as when we deal with a guest
IRQ, are added;
- tracing of IRQs handled with direct vectors is also
added.
With all the above, a trace will now look like this (using
xenalyze):
0.001299072 .x- d32768v5 irq_enter, irq 80000000
0.001299072 .x- d32768v5 irq_direct, vec fa, handler = 0xffff82d08026d7e4
0.001300014 .x- d32768v5 raise_softirq nr 0
0.001300487 .x- d32768v5 irq_exit irq 80000000, in_irq = 0
Or like this:
0.049437892 -|- d32767v12 irq_enter, irq 4
0.049437892 -|- d32767v12 irq_handled irq 4, 85428 cycles
0.049474336 -|- d32767v12 irq_exit irq 4, status = 0x0, in_irq = 0
Making it much easier to figure out when interrupt
processing start, what it does and when it ends.
Signed-off-by: Dario Faggioli <dario.faggioli@xxxxxxxxxx>
---
Cc: George Dunlap <george.dunlap@xxxxxxxxxxxxx>
Cc: Ian Jackson <ian.jackson@xxxxxxxxxxxxx>
Cc: Wei Liu <wei.liu2@xxxxxxxxxx>
Cc: Jan Beulich <jbeulich@xxxxxxxx>
Cc: Andrew Cooper <andrew.cooper3@xxxxxxxxxx>
---
tools/xentrace/formats | 6 ++++
tools/xentrace/xenalyze.c | 56 +++++++++++++++++++++++++++++++++++-----
xen/arch/x86/irq.c | 61 +++++++++++++++++++++++++++++++++++++-------
xen/include/public/trace.h | 4 +++
4 files changed, 109 insertions(+), 18 deletions(-)
diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 8b31780..00c29b8 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -197,7 +197,11 @@
0x00802005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) move_vector [ irq = %(1)d had
vector 0x%(2)x on CPU%(3)d ]
0x00802006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) assign_vector [ irq = %(1)d =
vector 0x%(2)x, CPU mask: 0x%(3)08x ]
0x00802007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) bogus_vector [ 0x%(1)x ]
-0x00802008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_irq [ irq = %(1)d, began =
%(2)dus, ended = %(3)dus ]
+0x00802008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) irq_handled [ irq = %(1)d, dur
= 0x%(3)08x%(2)08x ]
+0x00802009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) direct_vector [ vector
0x%(1)x, handler = 0x%(3)08x%(2)08x ]
+0x0080200a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_irq [ irq = %(1)d ]
+0x0080200b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_guest_irq [ irq = %(1)d ]
+0x0080200c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) irq_exit [ irq = %(1)d, status
= 0x%(2)x, in_irq = %(3)d ]
0x00084001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet create [ tn = %(1)d, irq
= %(2)d, delta = 0x%(4)08x%(3)08x, period = 0x%(6)08x%(5)08x ]
0x00084002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit create [ delta =
0x%(1)016x, period = 0x%(2)016x ]
diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index fa608ad..063eee7 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -8380,19 +8380,45 @@ void irq_process(struct pcpu_info *p) {
}
break;
}
- case TRC_HW_IRQ_HANDLED:
+ case TRC_HW_IRQ_ENTER:
+ case TRC_HW_IRQ_GUEST:
{
struct {
- int irq, start_tsc, end_tsc;
+ int32_t irq;
} *r = (typeof(r))ri->d;
- int arctime;
- arctime = r->end_tsc - r->start_tsc;
if ( opt.dump_all )
{
- printf(" %s irq_handled irq %x %d (%d,%d)\n",
- ri->dump_header,
- r->irq, arctime, r->start_tsc, r->end_tsc);
+ printf(" %s irq_%s, irq %x\n", ri->dump_header,
+ ri->event == TRC_HW_IRQ_ENTER ? "enter" : "guest", r->irq);
+ }
+ break;
+ }
+ case TRC_HW_IRQ_DIRECT_VECTOR:
+ {
+ struct {
+ uint32_t vec;
+ uint64_t handler;
+ } __attribute__((packed)) *r = (typeof(r))ri->d;
+
+ if ( opt.dump_all )
+ {
+ printf(" %s irq_direct, vec %x, handler = %p\n",
+ ri->dump_header, r->vec, (void*)r->handler);
+ }
+ break;
+ }
+ case TRC_HW_IRQ_HANDLED:
+ {
+ struct {
+ int32_t irq;
+ uint64_t arctime;
+ } __attribute__((packed)) *r = (typeof(r))ri->d;
+
+ if ( opt.dump_all )
+ {
+ printf(" %s irq_handled irq %x, %"PRIu64" cycles\n",
+ ri->dump_header, r->irq, r->arctime);
}
if ( opt.scatterplot_irq )
{
@@ -8407,6 +8433,22 @@ void irq_process(struct pcpu_info *p) {
}
break;
}
+ case TRC_HW_IRQ_EXIT:
+ {
+ struct {
+ int32_t irq, status;
+ uint32_t in_irq;
+ } *r = (typeof(r))ri->d;
+
+ if ( opt.dump_all )
+ {
+ printf(" %s irq_exit irq %x", ri->dump_header, r->irq);
+ if ( r->status != -1 )
+ printf(", status = 0x%x", r->status);
+ printf(", in_irq = %d\n", r->in_irq);
+ }
+ break;
+ }
case TRC_HW_IRQ_ASSIGN_VECTOR:
{
struct {
diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 676ba52..f5d9302 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -100,11 +100,15 @@ static void trace_irq_mask(u32 event, int irq, int
vector, cpumask_t *mask)
unsigned int irq:16, vec:16;
unsigned int mask[6];
} d;
+
+ if ( likely(!tb_init_done) )
+ return;
+
d.irq = irq;
d.vec = vector;
memset(d.mask, 0, sizeof(d.mask));
memcpy(d.mask, mask, min(sizeof(d.mask), sizeof(cpumask_t)));
- trace_var(event, 1, sizeof(d), &d);
+ __trace_var(event, 1, sizeof(d), &d);
}
static int __init __bind_irq_vector(int irq, int vector, const cpumask_t
*cpu_mask)
@@ -804,23 +808,54 @@ void alloc_direct_apic_vector(
spin_unlock(&lock);
}
+static inline void trace_irq_handled(int irq, uint64_t time)
+{
+ struct __packed {
+ int32_t irq;
+ uint64_t time;
+ } d;
+
+ if ( likely(!tb_init_done) )
+ return;
+
+ d.irq = irq;
+ d.time = time;
+ __trace_var(TRC_HW_IRQ_HANDLED, 0, sizeof(d), &d);
+}
+
void do_IRQ(struct cpu_user_regs *regs)
{
struct irqaction *action;
- uint32_t tsc_in;
- struct irq_desc *desc;
+ uint64_t tsc_in = 0;
+ struct irq_desc *desc = NULL;
unsigned int vector = (u8)regs->entry_vector;
int irq = __get_cpu_var(vector_irq[vector]);
struct cpu_user_regs *old_regs = set_irq_regs(regs);
perfc_incr(irqs);
this_cpu(irq_count)++;
+ TRACE_1D(TRC_HW_IRQ_ENTER, irq);
irq_enter();
- if (irq < 0) {
- if (direct_apic_vector[vector] != NULL) {
+ if (irq < 0)
+ {
+ if (direct_apic_vector[vector] != NULL)
+ {
+ if ( unlikely(tb_init_done) )
+ {
+ struct __packed {
+ uint32_t vec;
+ uint64_t handler;
+ } d;
+
+ d.vec = vector;
+ d.handler = (uint64_t)direct_apic_vector[vector];
+ __trace_var(TRC_HW_IRQ_DIRECT_VECTOR, 0, sizeof(d), &d);
+ }
(*direct_apic_vector[vector])(regs);
- } else {
+ }
+ else
+ {
const char *kind = ", LAPIC";
if ( apic_isr_read(vector) )
@@ -884,9 +919,13 @@ void do_IRQ(struct cpu_user_regs *regs)
desc->rl_quantum_start = now;
}
- tsc_in = tb_init_done ? get_cycles() : 0;
+ if ( unlikely(tb_init_done) )
+ {
+ __trace_var(TRC_HW_IRQ_GUEST, 0, sizeof(irq), &irq);
+ tsc_in = get_cycles();
+ }
__do_IRQ_guest(irq);
- TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles());
+ trace_irq_handled(irq, get_cycles() - tsc_in);
goto out_no_end;
}
@@ -907,9 +946,10 @@ void do_IRQ(struct cpu_user_regs *regs)
{
desc->status &= ~IRQ_PENDING;
spin_unlock_irq(&desc->lock);
- tsc_in = tb_init_done ? get_cycles() : 0;
+ if ( unlikely(tb_init_done) )
+ tsc_in = get_cycles();
action->handler(irq, action->dev_id, regs);
- TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles());
+ trace_irq_handled(irq, get_cycles() - tsc_in);
spin_lock_irq(&desc->lock);
}
@@ -922,6 +962,7 @@ void do_IRQ(struct cpu_user_regs *regs)
spin_unlock(&desc->lock);
out_no_unlock:
irq_exit();
+ TRACE_3D(TRC_HW_IRQ_EXIT, irq, desc == NULL ? -1 : desc->status, in_irq());
set_irq_regs(old_regs);
}
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index 7f2e891..f66a7af 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -271,6 +271,10 @@
#define TRC_HW_IRQ_ASSIGN_VECTOR (TRC_HW_IRQ + 0x6)
#define TRC_HW_IRQ_UNMAPPED_VECTOR (TRC_HW_IRQ + 0x7)
#define TRC_HW_IRQ_HANDLED (TRC_HW_IRQ + 0x8)
+#define TRC_HW_IRQ_DIRECT_VECTOR (TRC_HW_IRQ + 0x9)
+#define TRC_HW_IRQ_ENTER (TRC_HW_IRQ + 0xA)
+#define TRC_HW_IRQ_GUEST (TRC_HW_IRQ + 0xB)
+#define TRC_HW_IRQ_EXIT (TRC_HW_IRQ + 0xC)
/*
* Event Flags
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
https://lists.xen.org/xen-devel
|
 |
Lists.xenproject.org is hosted with RackSpace, monitoring our |