xentrace: Trace IRQs and entry/exit timestamps.

From: Dulloor <dulloor@gmail.com>
Signed-off-by: Keir Fraser <keir.fraser@citrix.com>

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 617e4745ad4c079175d0307170f353549bb0e2e0..5b2a7693d1cbbceea0ea2a17631295e0560837d7 100644 (file)
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -3,6 +3,7 @@
 0x0001f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  lost_records      0x%(1)08x
 0x0001f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  wrap_buffer       0x%(1)08x
 0x0001f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_change        0x%(1)08x
+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 ]
 
 0x00021011  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  running_to_runnable [ dom:vcpu = 0x%(1)08x ]
 0x00021021  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  running_to_blocked  [ dom:vcpu = 0x%(1)08x ]

diff --git a/tools/xentrace/xentrace_format b/tools/xentrace/xentrace_format
index f0127309abb9fb8650b36243c270450a886b21a2..e13b05b734a5f3e33ca3b1c6da77575750806bc2 100644 (file)
--- a/tools/xentrace/xentrace_format
+++ b/tools/xentrace/xentrace_format
@@ -110,6 +110,10 @@ D7REC  = "IIIIIII"
 
 last_tsc = [0]
 
+TRC_TRACE_IRQ = 0x1f004
+NR_VECTORS = 256
+irq_measure = [{'count':0, 'tot_cycles':0, 'max_cycles':0}] * NR_VECTORS
+
 i=0
 
 while not interrupted:
@@ -179,6 +183,19 @@ while not interrupted:
         if event == 0x1f003:
             cpu = d1
 
+        if event == TRC_TRACE_IRQ:
+            # IN - d1:vector, d2:tsc_in, d3:tsc_out
+            # OUT - d1:vector, d2:count, d3:tot_cycles, d4:max_cycles
+            tsc_diff = d3 - d2
+            if tsc_diff < 0:
+                break
+            irq_measure[d1]['count'] += 1
+            irq_measure[d1]['tot_cycles'] += tsc_diff
+            if irq_measure[d1]['max_cycles'] < tsc_diff:
+                irq_measure[d1]['max_cycles'] = tsc_diff
+            d2 = irq_measure[d1]['count']
+            d3 = irq_measure[d1]['tot_cycles']
+            d4 = irq_measure[d1]['max_cycles']
 
         #tsc = (tscH<<32) | tscL
 

diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 8c790cf7fef15596db61692fde20a6f041a8064c..57b3c59a20f7043819d2f049b4f3a1c25d3e4c33 100644 (file)
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -16,6 +16,7 @@
 #include <xen/compat.h>
 #include <xen/iocap.h>
 #include <xen/iommu.h>
+#include <xen/trace.h>
 #include <asm/msi.h>
 #include <asm/current.h>
 #include <asm/flushtlb.h>
@@ -114,6 +115,7 @@ asmlinkage void do_IRQ(struct cpu_user_regs *regs)
     unsigned int      vector = regs->entry_vector;
     irq_desc_t       *desc = &irq_desc[vector];
     struct irqaction *action;
+    uint32_t          tsc_in;
 
     perfc_incr(irqs);
 
@@ -123,7 +125,9 @@ asmlinkage void do_IRQ(struct cpu_user_regs *regs)
     if ( likely(desc->status & IRQ_GUEST) )
     {
         irq_enter();
+        tsc_in = tb_init_done ? get_cycles() : 0;
         __do_IRQ_guest(vector);
+        TRACE_3D(TRC_TRACE_IRQ, vector, tsc_in, get_cycles());
         irq_exit();
         spin_unlock(&desc->lock);
         return;
@@ -147,7 +151,9 @@ asmlinkage void do_IRQ(struct cpu_user_regs *regs)
         desc->status &= ~IRQ_PENDING;
         irq_enter();
         spin_unlock_irq(&desc->lock);
+        tsc_in = tb_init_done ? get_cycles() : 0;
         action->handler(vector_to_irq(vector), action->dev_id, regs);
+        TRACE_3D(TRC_TRACE_IRQ, vector, tsc_in, get_cycles());
         spin_lock_irq(&desc->lock);
         irq_exit();
     }

diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index 76088e346d27d23bb891ac1b5095fb70203ab863..6eb125a510afd560010869c4320769eaaf437769 100644 (file)
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -59,6 +59,7 @@
 #define TRC_LOST_RECORDS        (TRC_GEN + 1)
 #define TRC_TRACE_WRAP_BUFFER  (TRC_GEN + 2)
 #define TRC_TRACE_CPU_CHANGE    (TRC_GEN + 3)
+#define TRC_TRACE_IRQ           (TRC_GEN + 4)
 
 #define TRC_SCHED_RUNSTATE_CHANGE   (TRC_SCHED_MIN + 1)
 #define TRC_SCHED_CONTINUE_RUNNING  (TRC_SCHED_MIN + 2)