[PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing

[Dario Faggioli <dario.faggioli@citrix.com>]

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@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Jan Beulich <jbeulich@suse.com>
Cc: Andrew Cooper <andrew.cooper3@citrix.com>
---
 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@lists.xen.org
https://lists.xen.org/xen-devel