[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

 


Rackspace

Lists.xenproject.org is hosted with RackSpace, monitoring our
servers 24x7x365 and backed by RackSpace's Fanatical Support®.