|
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] Re: [Xen-devel] [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing
On 01/06/17 18:33, Dario Faggioli wrote:
> 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
Please consistently use 0x$hex. vec in particular has 10/16ths of its
values which are completely ambiguous between hex and decimal.
~Andrew
> 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);
irq %#x
> + }
> + 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);
vec %02x
> + }
> + 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",
irq %#x
> + 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)
Spaces.
> + {
> + if (direct_apic_vector[vector] != NULL)
Spaces.
> + {
> + 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];
As there is no code inbetween, you can do this as a straight
initialisation of d.
i.e.
} d = { vector, (uint64_t)direct_apic_vector[vector] };
Otherwise, Reviewed-by: Andrew Cooper <andrew.cooper3@xxxxxxxxxx>
> + __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 |