1.1 --- a/tools/xentrace/formats	Tue May 19 01:50:00 2009 +0100
     1.2 +++ b/tools/xentrace/formats	Tue May 19 02:08:01 2009 +0100
     1.3 @@ -3,6 +3,7 @@ 0x00000000  CPU%(cpu)d  %(tsc)d (+%(relt
     1.4  0x0001f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  lost_records      0x%(1)08x
     1.5  0x0001f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  wrap_buffer       0x%(1)08x
     1.6  0x0001f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_change        0x%(1)08x
     1.7 +0x0001f004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  trace_irq    [ vector = %(1)d, count = %(2)d, tot_cycles = 0x%(3)08x, max_cycles = 0x%(4)08x ]
     1.8  
     1.9  0x00021011  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  running_to_runnable [ dom:vcpu = 0x%(1)08x ]
    1.10  0x00021021  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  running_to_blocked  [ dom:vcpu = 0x%(1)08x ]

     2.1 --- a/tools/xentrace/xentrace_format	Tue May 19 01:50:00 2009 +0100
     2.2 +++ b/tools/xentrace/xentrace_format	Tue May 19 02:08:01 2009 +0100
     2.3 @@ -110,6 +110,10 @@ D7REC  = "IIIIIII"
     2.4  
     2.5  last_tsc = [0]
     2.6  
     2.7 +TRC_TRACE_IRQ = 0x1f004
     2.8 +NR_VECTORS = 256
     2.9 +irq_measure = [{'count':0, 'tot_cycles':0, 'max_cycles':0}] * NR_VECTORS
    2.10 +
    2.11  i=0
    2.12  
    2.13  while not interrupted:
    2.14 @@ -179,6 +183,19 @@ while not interrupted:
    2.15          if event == 0x1f003:
    2.16              cpu = d1
    2.17  
    2.18 +        if event == TRC_TRACE_IRQ:
    2.19 +            # IN - d1:vector, d2:tsc_in, d3:tsc_out
    2.20 +            # OUT - d1:vector, d2:count, d3:tot_cycles, d4:max_cycles
    2.21 +            tsc_diff = d3 - d2
    2.22 +            if tsc_diff < 0:
    2.23 +                break
    2.24 +            irq_measure[d1]['count'] += 1
    2.25 +            irq_measure[d1]['tot_cycles'] += tsc_diff
    2.26 +            if irq_measure[d1]['max_cycles'] < tsc_diff:
    2.27 +                irq_measure[d1]['max_cycles'] = tsc_diff
    2.28 +            d2 = irq_measure[d1]['count']
    2.29 +            d3 = irq_measure[d1]['tot_cycles']
    2.30 +            d4 = irq_measure[d1]['max_cycles']
    2.31  
    2.32          #tsc = (tscH<<32) | tscL
    2.33  

     3.1 --- a/xen/arch/x86/irq.c	Tue May 19 01:50:00 2009 +0100
     3.2 +++ b/xen/arch/x86/irq.c	Tue May 19 02:08:01 2009 +0100
     3.3 @@ -16,6 +16,7 @@
     3.4  #include <xen/compat.h>
     3.5  #include <xen/iocap.h>
     3.6  #include <xen/iommu.h>
     3.7 +#include <xen/trace.h>
     3.8  #include <asm/msi.h>
     3.9  #include <asm/current.h>
    3.10  #include <asm/flushtlb.h>
    3.11 @@ -114,6 +115,7 @@ asmlinkage void do_IRQ(struct cpu_user_r
    3.12      unsigned int      vector = regs->entry_vector;
    3.13      irq_desc_t       *desc = &irq_desc[vector];
    3.14      struct irqaction *action;
    3.15 +    uint32_t          tsc_in;
    3.16  
    3.17      perfc_incr(irqs);
    3.18  
    3.19 @@ -123,7 +125,9 @@ asmlinkage void do_IRQ(struct cpu_user_r
    3.20      if ( likely(desc->status & IRQ_GUEST) )
    3.21      {
    3.22          irq_enter();
    3.23 +        tsc_in = tb_init_done ? get_cycles() : 0;
    3.24          __do_IRQ_guest(vector);
    3.25 +        TRACE_3D(TRC_TRACE_IRQ, vector, tsc_in, get_cycles());
    3.26          irq_exit();
    3.27          spin_unlock(&desc->lock);
    3.28          return;
    3.29 @@ -147,7 +151,9 @@ asmlinkage void do_IRQ(struct cpu_user_r
    3.30          desc->status &= ~IRQ_PENDING;
    3.31          irq_enter();
    3.32          spin_unlock_irq(&desc->lock);
    3.33 +        tsc_in = tb_init_done ? get_cycles() : 0;
    3.34          action->handler(vector_to_irq(vector), action->dev_id, regs);
    3.35 +        TRACE_3D(TRC_TRACE_IRQ, vector, tsc_in, get_cycles());
    3.36          spin_lock_irq(&desc->lock);
    3.37          irq_exit();
    3.38      }

     4.1 --- a/xen/include/public/trace.h	Tue May 19 01:50:00 2009 +0100
     4.2 +++ b/xen/include/public/trace.h	Tue May 19 02:08:01 2009 +0100
     4.3 @@ -59,6 +59,7 @@
     4.4  #define TRC_LOST_RECORDS        (TRC_GEN + 1)
     4.5  #define TRC_TRACE_WRAP_BUFFER  (TRC_GEN + 2)
     4.6  #define TRC_TRACE_CPU_CHANGE    (TRC_GEN + 3)
     4.7 +#define TRC_TRACE_IRQ           (TRC_GEN + 4)
     4.8  
     4.9  #define TRC_SCHED_RUNSTATE_CHANGE   (TRC_SCHED_MIN + 1)
    4.10  #define TRC_SCHED_CONTINUE_RUNNING  (TRC_SCHED_MIN + 2)