[PATCH v2 0/2] xentrace: Add TRC_HVM_VCHIP (was xentrace: Add TRC_HW_VCHIP).

[PATCH v2 0/2] xentrace: Add TRC_HVM_VCHIP (was xentrace: Add TRC_HW_VCHIP).

[Don Slutz]

Changes v1 to v2:
  Tim Deegan:
    Switch from TRC_HW_VCHIP to TRC_HVM_VCHIP.
    Drop get_cycles()
    Fix coding style issues.
    Drop code that should not have been included.
    Use names not numbers.

Split in 2 patches for simpler review.

Here is a subset of sample output:

dcs-xen-54:~/xen>grep hpet /home/don/zz-xentrace-3.out     
CPU5  841028423232 (+    3900)  hpet create [ tn = 0, irq = 0, delta = 848080, period = 1000000 ]
CPU1  843516134148 (+   20796)  hpet destroy [ tn = 0 ]
CPU7  846913412784 (+   26184)  hpet destroy [ tn = 0 ]
CPU7  846913416102 (+    1776)  hpet create [ tn = 0, irq = 0, delta = 4170764048, period = 0 ]
CPU4  851697560919 (+   11499)  hpet destroy [ tn = 1 ]
CPU4  851697562041 (+    1122)  hpet create [ tn = 1, irq = 8, delta = 15605920, period = 0 ]
CPU4  851765523993 (+   12567)  hpet destroy [ tn = 1 ]
CPU5  1139751965382 (+   18624)  hpet create [ tn = 1, irq = 8, delta = 15598912, period = 0 ]
CPU5  1139789579136 (+   23088)  hpet destroy [ tn = 1 ]
CPU5  1139789581410 (+    2274)  hpet create [ tn = 1, irq = 8, delta = 15550992, period = 0 ]
CPU5  1139827080720 (+   24174)  hpet destroy [ tn = 1 ]
CPU5  1139827082718 (+    1998)  hpet create [ tn = 1, irq = 8, delta = 15550912, period = 0 ]
CPU5  1139864572410 (+   21198)  hpet destroy [ tn = 1 ]
CPU5  1139864574390 (+    1980)  hpet create [ tn = 1, irq = 8, delta = 15554912, period = 0 ]
CPU5  1139902073244 (+   21180)  hpet destroy [ tn = 1 ]
CPU5  1139902075296 (+    2052)  hpet create [ tn = 1, irq = 8, delta = 15555056, period = 0 ]
CPU5  1139939593674 (+   29112)  hpet destroy [ tn = 1 ]
CPU5  1139939595870 (+    2196)  hpet create [ tn = 1, irq = 8, delta = 15546992, period = 0 ]
CPU5  1139977075716 (+   21048)  hpet destroy [ tn = 1 ]
CPU5  1139977077642 (+    1926)  hpet create [ tn = 1, irq = 8, delta = 15555104, period = 0 ]
CPU5  1140014582832 (+   23088)  hpet destroy [ tn = 1 ]
CPU5  1140014584950 (+    2118)  hpet create [ tn = 1, irq = 8, delta = 15552576, period = 0 ]
CPU5  1140038873628 (+   21150)  hpet destroy [ tn = 1 ]
CPU5  1140038875890 (+    2262)  hpet create [ tn = 1, irq = 8, delta = 21056672, period = 0 ]
CPU5  1140039140484 (+   18348)  hpet destroy [ tn = 1 ]
CPU6  1142224601952 (+   12486)  hpet destroy [ tn = 0 ]



Don Slutz (2):
  xentrace: Add emacs local variables
  xentrace: Add TRC_HVM_VCHIP

 tools/xentrace/formats     | 18 ++++++++++++++++++
 xen/arch/x86/hvm/hpet.c    | 14 ++++++++++++++
 xen/arch/x86/hvm/i8254.c   | 18 ++++++++++++++++++
 xen/arch/x86/hvm/rtc.c     | 18 ++++++++++++++++++
 xen/arch/x86/hvm/vlapic.c  | 25 +++++++++++++++++++++++++
 xen/arch/x86/hvm/vpic.c    | 20 ++++++++++++++++++++
 xen/include/public/trace.h | 20 ++++++++++++++++++++
 7 files changed, 133 insertions(+)

-- 
1.8.4

[PATCH v2 1/2] xentrace: Add emacs local variables

[Don Slutz]

This is per CODING_STYLE.

Signed-off-by: Don Slutz <dslutz@verizon.com>
---
 xen/arch/x86/hvm/hpet.c   | 9 +++++++++
 xen/arch/x86/hvm/i8254.c  | 9 +++++++++
 xen/arch/x86/hvm/rtc.c    | 9 +++++++++
 xen/arch/x86/hvm/vlapic.c | 9 +++++++++
 xen/arch/x86/hvm/vpic.c   | 9 +++++++++
 5 files changed, 45 insertions(+)

diff --git a/xen/arch/x86/hvm/hpet.c b/xen/arch/x86/hvm/hpet.c
index 4324b52..e1e769a 100644
--- a/xen/arch/x86/hvm/hpet.c
+++ b/xen/arch/x86/hvm/hpet.c
@@ -622,3 +622,12 @@ void hpet_reset(struct domain *d)
     hpet_deinit(d);
     hpet_init(d->vcpu[0]);
 }
+
+/*
+ * Local variables:
+ * mode: C
+ * c-file-style: "BSD"
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * End:
+ */
diff --git a/xen/arch/x86/hvm/i8254.c b/xen/arch/x86/hvm/i8254.c
index f7493b8..6e66b49 100644
--- a/xen/arch/x86/hvm/i8254.c
+++ b/xen/arch/x86/hvm/i8254.c
@@ -556,3 +556,12 @@ int pv_pit_handler(int port, int data, int write)
 
     return !write ? ioreq.data : 0;
 }
+
+/*
+ * Local variables:
+ * mode: C
+ * c-file-style: "BSD"
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * End:
+ */
diff --git a/xen/arch/x86/hvm/rtc.c b/xen/arch/x86/hvm/rtc.c
index 639b4c5..7cd0cf4 100644
--- a/xen/arch/x86/hvm/rtc.c
+++ b/xen/arch/x86/hvm/rtc.c
@@ -827,3 +827,12 @@ void rtc_update_clock(struct domain *d)
     s->current_tm = gmtime(get_localtime(d));
     spin_unlock(&s->lock);
 }
+
+/*
+ * Local variables:
+ * mode: C
+ * c-file-style: "BSD"
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * End:
+ */
diff --git a/xen/arch/x86/hvm/vlapic.c b/xen/arch/x86/hvm/vlapic.c
index bc06010..fc307c0 100644
--- a/xen/arch/x86/hvm/vlapic.c
+++ b/xen/arch/x86/hvm/vlapic.c
@@ -1279,3 +1279,12 @@ void vlapic_destroy(struct vcpu *v)
     unmap_domain_page_global(vlapic->regs);
     free_domheap_page(vlapic->regs_page);
 }
+
+/*
+ * Local variables:
+ * mode: C
+ * c-file-style: "BSD"
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * End:
+ */
diff --git a/xen/arch/x86/hvm/vpic.c b/xen/arch/x86/hvm/vpic.c
index fea3f68..5ca513c 100644
--- a/xen/arch/x86/hvm/vpic.c
+++ b/xen/arch/x86/hvm/vpic.c
@@ -473,3 +473,12 @@ int vpic_ack_pending_irq(struct vcpu *v)
     vector = vpic[irq >> 3].irq_base + (irq & 7);
     return vector;
 }
+
+/*
+ * Local variables:
+ * mode: C
+ * c-file-style: "BSD"
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * End:
+ */
-- 
1.8.4

Re: [PATCH v2 1/2] xentrace: Add emacs local variables

[George Dunlap]

On Fri, Mar 28, 2014 at 4:56 PM, Don Slutz <dslutz@verizon.com> wrote:
> This is per CODING_STYLE.
>
> Signed-off-by: Don Slutz <dslutz@verizon.com>

Er, this change doesn't have anything to do with xentrace; it's a bit
misleading to have that in the short description.

 -George

Re: [PATCH v2 1/2] xentrace: Add emacs local variables

[Don Slutz]

On 04/01/14 05:16, George Dunlap wrote:
> On Fri, Mar 28, 2014 at 4:56 PM, Don Slutz <dslutz@verizon.com> wrote:
>> This is per CODING_STYLE.
>>
>> Signed-off-by: Don Slutz <dslutz@verizon.com>
> Er, this change doesn't have anything to do with xentrace; it's a bit
> misleading to have that in the short description.

Ok.  How about:

Add emacs local variables to all files changed.

    -Don Slutz

>   -George

[PATCH v2 2/2] xentrace: Add TRC_HVM_VCHIP

[Don Slutz]

This add a set of trace events that track the setup of various
virtual chips related to timers in domU.

This set is hpet, pit (i8253, i8254), rtc (MC146818), apic (lapic),
and pic (i8259).  The pmtimer is not traced since it does not have a
changeable rate.

Signed-off-by: Don Slutz <dslutz@verizon.com>
---
 tools/xentrace/formats     | 18 ++++++++++++++++++
 xen/arch/x86/hvm/hpet.c    |  5 +++++
 xen/arch/x86/hvm/i8254.c   |  9 +++++++++
 xen/arch/x86/hvm/rtc.c     |  9 +++++++++
 xen/arch/x86/hvm/vlapic.c  | 16 ++++++++++++++++
 xen/arch/x86/hvm/vpic.c    | 11 +++++++++++
 xen/include/public/trace.h | 20 ++++++++++++++++++++
 7 files changed, 88 insertions(+)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 67fd42d..1d28e2a 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -152,3 +152,21 @@
 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 ]
+
+0x00084001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hpet create [ tn = %(1)d, irq = %(2)d, delta = %(3)d, period = %(4)d ]
+0x00084002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit create [ delta = %(1)d, period = %(2)d ]
+0x00084003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtc create [ delta = %(1)d, period = %(2)d ]
+0x00084004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic create [ delta = %(1)d, period = %(2)d, irq = %(3)d ]
+0x00084005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hpet destroy [ tn = %(1)d ]
+0x00084006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit destroy  [ ]
+0x00084007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtc destroy [ ]
+0x00084008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic destroy [ ]
+0x00084009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit callback [ ]
+0x0008400a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic callback [ ]
+0x0008400b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_update_int_output [ int_output = %(1)d, is_master = %(2)d, irq = %(3)d ]
+0x0008400c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic vcpu_kick [ irq = %(1)d ]
+0x0008400d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __vpic_intack [ is_master = %(1)d, irq = %(2)d ]
+0x0008400e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_irq_positive_edge [ irq = %(1)d ]
+0x0008400f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_irq_negative_edge [ irq = %(1)d ]
+0x00084010  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_ack_pending_irq [ accept_pic_intr = %(1)d, int_output = %(2)d ]
+0x00084011  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic_accept_pic_intr [ i8259_target = %(1)d, accept_pic_int = %(2)d ]
diff --git a/xen/arch/x86/hvm/hpet.c b/xen/arch/x86/hvm/hpet.c
index e1e769a..bb6de72 100644
--- a/xen/arch/x86/hvm/hpet.c
+++ b/xen/arch/x86/hvm/hpet.c
@@ -24,6 +24,7 @@
 #include <asm/hpet.h>
 #include <xen/sched.h>
 #include <xen/event.h>
+#include <xen/trace.h>
 
 #define domain_vhpet(x) (&(x)->arch.hvm_domain.pl_time.vhpet)
 #define vcpu_vhpet(x)   (domain_vhpet((x)->domain))
@@ -191,6 +192,7 @@ static void hpet_stop_timer(HPETState *h, unsigned int tn)
 {
     ASSERT(tn < HPET_TIMER_NUM);
     ASSERT(spin_is_locked(&h->lock));
+    TRACE_1D(TRC_HVM_VCHIP_HPET_STOP_TIMER, tn);
     destroy_periodic_time(&h->pt[tn]);
     /* read the comparator to get it updated so a read while stopped will
      * return the expected value. */
@@ -255,6 +257,9 @@ static void hpet_set_timer(HPETState *h, unsigned int tn)
      * being enabled (now).
      */
     oneshot = !timer_is_periodic(h, tn);
+    TRACE_4D(TRC_HVM_VCHIP_HPET_START_TIMER, tn, irq,
+             hpet_tick_to_ns(h, diff),
+             oneshot ? 0 : hpet_tick_to_ns(h, h->hpet.period[tn]));
     create_periodic_time(vhpet_vcpu(h), &h->pt[tn],
                          hpet_tick_to_ns(h, diff),
                          oneshot ? 0 : hpet_tick_to_ns(h, h->hpet.period[tn]),
diff --git a/xen/arch/x86/hvm/i8254.c b/xen/arch/x86/hvm/i8254.c
index 6e66b49..697d31b 100644
--- a/xen/arch/x86/hvm/i8254.c
+++ b/xen/arch/x86/hvm/i8254.c
@@ -31,6 +31,7 @@
 #include <xen/lib.h>
 #include <xen/errno.h>
 #include <xen/sched.h>
+#include <xen/trace.h>
 #include <asm/time.h>
 #include <asm/hvm/hvm.h>
 #include <asm/hvm/io.h>
@@ -159,6 +160,7 @@ static int pit_get_gate(PITState *pit, int channel)
 static void pit_time_fired(struct vcpu *v, void *priv)
 {
     uint64_t *count_load_time = priv;
+    TRACE_0D(TRC_HVM_VCHIP_PIT_TIMER_CB);
     *count_load_time = get_guest_time(v);
 }
 
@@ -188,16 +190,19 @@ static void pit_load_count(PITState *pit, int channel, int val)
     case 2:
     case 3:
         /* Periodic timer. */
+        TRACE_2D(TRC_HVM_VCHIP_PIT_START_TIMER, period, period);
         create_periodic_time(v, &pit->pt0, period, period, 0, pit_time_fired, 
                              &pit->count_load_time[channel]);
         break;
     case 1:
     case 4:
         /* One-shot timer. */
+        TRACE_2D(TRC_HVM_VCHIP_PIT_START_TIMER, period, 0);
         create_periodic_time(v, &pit->pt0, period, 0, 0, pit_time_fired,
                              &pit->count_load_time[channel]);
         break;
     default:
+        TRACE_0D(TRC_HVM_VCHIP_PIT_STOP_TIMER);
         destroy_periodic_time(&pit->pt0);
         break;
     }
@@ -377,6 +382,7 @@ static uint32_t pit_ioport_read(struct PITState *pit, uint32_t addr)
 
 void pit_stop_channel0_irq(PITState *pit)
 {
+    TRACE_0D(TRC_HVM_VCHIP_PIT_STOP_TIMER);
     spin_lock(&pit->lock);
     destroy_periodic_time(&pit->pt0);
     spin_unlock(&pit->lock);
@@ -431,6 +437,7 @@ void pit_reset(struct domain *d)
     struct hvm_hw_pit_channel *s;
     int i;
 
+    TRACE_0D(TRC_HVM_VCHIP_PIT_STOP_TIMER);
     destroy_periodic_time(&pit->pt0);
     pit->pt0.source = PTSRC_isa;
 
@@ -465,6 +472,8 @@ void pit_init(struct domain *d, unsigned long cpu_khz)
 void pit_deinit(struct domain *d)
 {
     PITState *pit = domain_vpit(d);
+
+    TRACE_0D(TRC_HVM_VCHIP_PIT_STOP_TIMER);
     destroy_periodic_time(&pit->pt0);
 }
 
diff --git a/xen/arch/x86/hvm/rtc.c b/xen/arch/x86/hvm/rtc.c
index 7cd0cf4..5fb6e01 100644
--- a/xen/arch/x86/hvm/rtc.c
+++ b/xen/arch/x86/hvm/rtc.c
@@ -27,6 +27,7 @@
 #include <asm/hvm/io.h>
 #include <asm/hvm/support.h>
 #include <asm/current.h>
+#include <xen/trace.h>
 
 #define USEC_PER_SEC    1000000UL
 #define NS_PER_USEC     1000UL
@@ -91,6 +92,7 @@ static void rtc_pf_callback(struct vcpu *v, void *opaque)
          && ++(s->pt_dead_ticks) >= 10 )
     {
         /* VM is ignoring its RTC; no point in running the timer */
+        TRACE_0D(TRC_HVM_VCHIP_RTC_STOP_TIMER);
         destroy_periodic_time(&s->pt);
         s->period = 0;
     }
@@ -152,8 +154,11 @@ static void rtc_timer_update(RTCState *s)
                 else
                     delta = period - ((now - s->start_time) % period);
                 if ( s->hw.cmos_data[RTC_REG_B] & RTC_PIE )
+                {
+                    TRACE_2D(TRC_HVM_VCHIP_RTC_START_TIMER, delta, period);
                     create_periodic_time(v, &s->pt, delta, period,
                                          RTC_IRQ, rtc_pf_callback, s);
+                }
                 else
                     s->check_ticks_since = now;
             }
@@ -161,6 +166,7 @@ static void rtc_timer_update(RTCState *s)
         }
         /* fall through */
     default:
+        TRACE_0D(TRC_HVM_VCHIP_RTC_STOP_TIMER);
         destroy_periodic_time(&s->pt);
         s->period = 0;
         break;
@@ -513,6 +519,7 @@ static int rtc_ioport_write(void *opaque, uint32_t addr, uint32_t data)
         rtc_update_irq(s);
         if ( (data ^ orig) & RTC_PIE )
         {
+            TRACE_0D(TRC_HVM_VCHIP_RTC_STOP_TIMER);
             destroy_periodic_time(&s->pt);
             s->period = 0;
             rtc_timer_update(s);
@@ -772,6 +779,7 @@ void rtc_reset(struct domain *d)
 {
     RTCState *s = domain_vrtc(d);
 
+    TRACE_0D(TRC_HVM_VCHIP_RTC_STOP_TIMER);
     destroy_periodic_time(&s->pt);
     s->period = 0;
     s->pt.source = PTSRC_isa;
@@ -813,6 +821,7 @@ void rtc_deinit(struct domain *d)
 
     spin_barrier(&s->lock);
 
+    TRACE_0D(TRC_HVM_VCHIP_RTC_STOP_TIMER);
     destroy_periodic_time(&s->pt);
     kill_timer(&s->update_timer);
     kill_timer(&s->update_timer2);
diff --git a/xen/arch/x86/hvm/vlapic.c b/xen/arch/x86/hvm/vlapic.c
index fc307c0..d4ee283 100644
--- a/xen/arch/x86/hvm/vlapic.c
+++ b/xen/arch/x86/hvm/vlapic.c
@@ -611,6 +611,7 @@ int hvm_x2apic_msr_read(struct vcpu *v, unsigned int msr, uint64_t *msr_content)
 
 static void vlapic_pt_cb(struct vcpu *v, void *data)
 {
+    TRACE_0D(TRC_HVM_VCHIP_LAPIC_TIMER_CB);
     *(s_time_t *)data = hvm_get_guest_time(v);
 }
 
@@ -712,6 +713,7 @@ static int vlapic_reg_write(struct vcpu *v,
         if ( (vlapic_get_reg(vlapic, offset) & APIC_TIMER_MODE_MASK) !=
              (val & APIC_TIMER_MODE_MASK) )
         {
+            TRACE_0D(TRC_HVM_VCHIP_LAPIC_STOP_TIMER);
             destroy_periodic_time(&vlapic->pt);
             vlapic_set_reg(vlapic, APIC_TMICT, 0);
             vlapic_set_reg(vlapic, APIC_TMCCT, 0);
@@ -746,12 +748,15 @@ static int vlapic_reg_write(struct vcpu *v,
         vlapic_set_reg(vlapic, APIC_TMICT, val);
         if ( val == 0 )
         {
+            TRACE_0D(TRC_HVM_VCHIP_LAPIC_STOP_TIMER);
             destroy_periodic_time(&vlapic->pt);
             break;
         }
 
         period = ((uint64_t)APIC_BUS_CYCLE_NS *
                   (uint32_t)val * vlapic->hw.timer_divisor);
+        TRACE_3D(TRC_HVM_VCHIP_LAPIC_START_TIMER, period,
+                 vlapic_lvtt_period(vlapic) ? period : 0, vlapic->pt.irq);
         create_periodic_time(current, &vlapic->pt, period, 
                              vlapic_lvtt_period(vlapic) ? period : 0,
                              vlapic->pt.irq,
@@ -950,6 +955,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value)
 
         vlapic->hw.tdt_msr = value;
         /* .... reprogram tdt timer */
+        TRACE_3D(TRC_HVM_VCHIP_LAPIC_START_TIMER, delta, 0, vlapic->pt.irq);
         create_periodic_time(v, &vlapic->pt, delta, 0,
                              vlapic->pt.irq, vlapic_tdt_pt_cb,
                              &vlapic->timer_last_update);
@@ -962,6 +968,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value)
         /* trigger a timer event if needed */
         if ( value > 0 )
         {
+            TRACE_3D(TRC_HVM_VCHIP_LAPIC_START_TIMER, 0, 0, vlapic->pt.irq);
             create_periodic_time(v, &vlapic->pt, 0, 0,
                                  vlapic->pt.irq, vlapic_tdt_pt_cb,
                                  &vlapic->timer_last_update);
@@ -970,6 +977,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value)
         else
         {
             /* .... stop tdt timer */
+            TRACE_0D(TRC_HVM_VCHIP_LAPIC_STOP_TIMER);
             destroy_periodic_time(&vlapic->pt);
         }
 
@@ -1003,6 +1011,10 @@ static int __vlapic_accept_pic_intr(struct vcpu *v)
 
 int vlapic_accept_pic_intr(struct vcpu *v)
 {
+    TRACE_2D(TRC_HVM_VCHIP_LAPIC_PIC_INTR,
+             (v == v->domain->arch.hvm_domain.i8259_target),
+             v ? __vlapic_accept_pic_intr(v) : -1);
+
     return ((v == v->domain->arch.hvm_domain.i8259_target) &&
             __vlapic_accept_pic_intr(v));
 }
@@ -1106,6 +1118,7 @@ void vlapic_reset(struct vlapic *vlapic)
     vlapic_set_reg(vlapic, APIC_SPIV, 0xff);
     vlapic->hw.disabled |= VLAPIC_SW_DISABLED;
 
+    TRACE_0D(TRC_HVM_VCHIP_LAPIC_STOP_TIMER);
     destroy_periodic_time(&vlapic->pt);
 }
 
@@ -1129,6 +1142,8 @@ static void lapic_rearm(struct vlapic *s)
 
     period = ((uint64_t)APIC_BUS_CYCLE_NS *
               (uint32_t)tmict * s->hw.timer_divisor);
+    TRACE_3D(TRC_HVM_VCHIP_LAPIC_START_TIMER, period,
+             vlapic_lvtt_period(s) ? period : 0, s->pt.irq);
     create_periodic_time(vlapic_vcpu(s), &s->pt, period,
                          vlapic_lvtt_period(s) ? period : 0,
                          s->pt.irq,
@@ -1275,6 +1290,7 @@ void vlapic_destroy(struct vcpu *v)
     struct vlapic *vlapic = vcpu_vlapic(v);
 
     tasklet_kill(&vlapic->init_sipi.tasklet);
+    TRACE_0D(TRC_HVM_VCHIP_LAPIC_STOP_TIMER);
     destroy_periodic_time(&vlapic->pt);
     unmap_domain_page_global(vlapic->regs);
     free_domheap_page(vlapic->regs_page);
diff --git a/xen/arch/x86/hvm/vpic.c b/xen/arch/x86/hvm/vpic.c
index 5ca513c..efa308e 100644
--- a/xen/arch/x86/hvm/vpic.c
+++ b/xen/arch/x86/hvm/vpic.c
@@ -30,6 +30,7 @@
 #include <xen/lib.h>
 #include <xen/errno.h>
 #include <xen/sched.h>
+#include <xen/trace.h>
 #include <asm/hvm/hvm.h>
 #include <asm/hvm/io.h>
 #include <asm/hvm/support.h>
@@ -99,6 +100,8 @@ static void vpic_update_int_output(struct hvm_hw_vpic *vpic)
     ASSERT(vpic_is_locked(vpic));
 
     irq = vpic_get_highest_priority_irq(vpic);
+    TRACE_3D(TRC_HVM_VCHIP_PIC_INT_OUTPUT, vpic->int_output, vpic->is_master,
+             irq);
     if ( vpic->int_output == (irq >= 0) )
         return;
 
@@ -112,7 +115,10 @@ static void vpic_update_int_output(struct hvm_hw_vpic *vpic)
             /* Master INT line is connected in Virtual Wire Mode. */
             struct vcpu *v = vpic_domain(vpic)->arch.hvm_domain.i8259_target;
             if ( v != NULL )
+            {
+                TRACE_1D(TRC_HVM_VCHIP_PIC_KICK, irq);
                 vcpu_kick(v);
+            }
         }
         else
         {
@@ -135,6 +141,7 @@ static void __vpic_intack(struct hvm_hw_vpic *vpic, int irq)
 
     ASSERT(vpic_is_locked(vpic));
 
+    TRACE_2D(TRC_HVM_VCHIP_PIC_INTACK, vpic->is_master, irq);
     /* Edge-triggered: clear the IRR (forget the edge). */
     if ( !(vpic->elcr & mask) )
         vpic->irr &= ~mask;
@@ -434,6 +441,7 @@ void vpic_irq_positive_edge(struct domain *d, int irq)
     ASSERT(irq <= 15);
     ASSERT(vpic_is_locked(vpic));
 
+    TRACE_1D(TRC_HVM_VCHIP_PIC_POSEDGE, irq);
     if ( irq == 2 )
         return;
 
@@ -450,6 +458,7 @@ void vpic_irq_negative_edge(struct domain *d, int irq)
     ASSERT(irq <= 15);
     ASSERT(vpic_is_locked(vpic));
 
+    TRACE_1D(TRC_HVM_VCHIP_PIC_NEGEDGE, irq);
     if ( irq == 2 )
         return;
 
@@ -463,6 +472,8 @@ int vpic_ack_pending_irq(struct vcpu *v)
     int irq, vector;
     struct hvm_hw_vpic *vpic = &v->domain->arch.hvm_domain.vpic[0];
 
+    TRACE_2D(TRC_HVM_VCHIP_PIC_PEND_IRQ_CALL, vlapic_accept_pic_intr(v),
+             vpic->int_output);
     if ( !vlapic_accept_pic_intr(v) || !vpic->int_output )
         return -1;
 
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index e2f60a6..410f0fe 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -52,6 +52,7 @@
 /* trace subclasses for SVM */
 #define TRC_HVM_ENTRYEXIT 0x00081000   /* VMENTRY and #VMEXIT       */
 #define TRC_HVM_HANDLER   0x00082000   /* various HVM handlers      */
+#define TRC_HVM_VCHIP     0x00084000   /* virtual chips */
 
 #define TRC_SCHED_MIN       0x00021000   /* Just runstate changes */
 #define TRC_SCHED_CLASS     0x00022000   /* Scheduler-specific    */
@@ -229,6 +230,25 @@
 #define TRC_HVM_IOPORT_WRITE    (TRC_HVM_HANDLER + 0x216)
 #define TRC_HVM_IOMEM_WRITE     (TRC_HVM_HANDLER + 0x217)
 
+/* Trace events for virtual chips */
+#define TRC_HVM_VCHIP_HPET_START_TIMER  (TRC_HVM_VCHIP + 0x1)
+#define TRC_HVM_VCHIP_PIT_START_TIMER   (TRC_HVM_VCHIP + 0x2)
+#define TRC_HVM_VCHIP_RTC_START_TIMER   (TRC_HVM_VCHIP + 0x3)
+#define TRC_HVM_VCHIP_LAPIC_START_TIMER (TRC_HVM_VCHIP + 0x4)
+#define TRC_HVM_VCHIP_HPET_STOP_TIMER   (TRC_HVM_VCHIP + 0x5)
+#define TRC_HVM_VCHIP_PIT_STOP_TIMER    (TRC_HVM_VCHIP + 0x6)
+#define TRC_HVM_VCHIP_RTC_STOP_TIMER    (TRC_HVM_VCHIP + 0x7)
+#define TRC_HVM_VCHIP_LAPIC_STOP_TIMER  (TRC_HVM_VCHIP + 0x8)
+#define TRC_HVM_VCHIP_PIT_TIMER_CB      (TRC_HVM_VCHIP + 0x9)
+#define TRC_HVM_VCHIP_LAPIC_TIMER_CB    (TRC_HVM_VCHIP + 0xA)
+#define TRC_HVM_VCHIP_PIC_INT_OUTPUT    (TRC_HVM_VCHIP + 0xB)
+#define TRC_HVM_VCHIP_PIC_KICK          (TRC_HVM_VCHIP + 0xC)
+#define TRC_HVM_VCHIP_PIC_INTACK        (TRC_HVM_VCHIP + 0xD)
+#define TRC_HVM_VCHIP_PIC_POSEDGE       (TRC_HVM_VCHIP + 0xE)
+#define TRC_HVM_VCHIP_PIC_NEGEDGE       (TRC_HVM_VCHIP + 0xF)
+#define TRC_HVM_VCHIP_PIC_PEND_IRQ_CALL (TRC_HVM_VCHIP + 0x10)
+#define TRC_HVM_VCHIP_LAPIC_PIC_INTR    (TRC_HVM_VCHIP + 0x11)
+
 /* trace events for per class */
 #define TRC_PM_FREQ_CHANGE      (TRC_HW_PM + 0x01)
 #define TRC_PM_IDLE_ENTRY       (TRC_HW_PM + 0x02)
-- 
1.8.4

Re: [PATCH v2 2/2] xentrace: Add TRC_HVM_VCHIP

[George Dunlap]

On 03/28/2014 04:56 PM, Don Slutz wrote:
> This add a set of trace events that track the setup of various
> virtual chips related to timers in domU.
>
> This set is hpet, pit (i8253, i8254), rtc (MC146818), apic (lapic),
> and pic (i8259).  The pmtimer is not traced since it does not have a
> changeable rate.
>
> Signed-off-by: Don Slutz <dslutz@verizon.com>
> ---
>   tools/xentrace/formats     | 18 ++++++++++++++++++
>   xen/arch/x86/hvm/hpet.c    |  5 +++++
>   xen/arch/x86/hvm/i8254.c   |  9 +++++++++
>   xen/arch/x86/hvm/rtc.c     |  9 +++++++++
>   xen/arch/x86/hvm/vlapic.c  | 16 ++++++++++++++++
>   xen/arch/x86/hvm/vpic.c    | 11 +++++++++++
>   xen/include/public/trace.h | 20 ++++++++++++++++++++
>   7 files changed, 88 insertions(+)
>
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index 67fd42d..1d28e2a 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -152,3 +152,21 @@
>   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 ]
> +
> +0x00084001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hpet create [ tn = %(1)d, irq = %(2)d, delta = %(3)d, period = %(4)d ]
> +0x00084002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit create [ delta = %(1)d, period = %(2)d ]
> +0x00084003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtc create [ delta = %(1)d, period = %(2)d ]
> +0x00084004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic create [ delta = %(1)d, period = %(2)d, irq = %(3)d ]
> +0x00084005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hpet destroy [ tn = %(1)d ]
> +0x00084006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit destroy  [ ]
> +0x00084007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtc destroy [ ]
> +0x00084008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic destroy [ ]
> +0x00084009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  pit callback [ ]
> +0x0008400a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic callback [ ]
> +0x0008400b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_update_int_output [ int_output = %(1)d, is_master = %(2)d, irq = %(3)d ]
> +0x0008400c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic vcpu_kick [ irq = %(1)d ]
> +0x0008400d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __vpic_intack [ is_master = %(1)d, irq = %(2)d ]
> +0x0008400e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_irq_positive_edge [ irq = %(1)d ]
> +0x0008400f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_irq_negative_edge [ irq = %(1)d ]
> +0x00084010  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vpic_ack_pending_irq [ accept_pic_intr = %(1)d, int_output = %(2)d ]
> +0x00084011  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  vlapic_accept_pic_intr [ i8259_target = %(1)d, accept_pic_int = %(2)d ]
> diff --git a/xen/arch/x86/hvm/hpet.c b/xen/arch/x86/hvm/hpet.c
> index e1e769a..bb6de72 100644
> --- a/xen/arch/x86/hvm/hpet.c
> +++ b/xen/arch/x86/hvm/hpet.c
> @@ -24,6 +24,7 @@
>   #include <asm/hpet.h>
>   #include <xen/sched.h>
>   #include <xen/event.h>
> +#include <xen/trace.h>
>
>   #define domain_vhpet(x) (&(x)->arch.hvm_domain.pl_time.vhpet)
>   #define vcpu_vhpet(x)   (domain_vhpet((x)->domain))
> @@ -191,6 +192,7 @@ static void hpet_stop_timer(HPETState *h, unsigned int tn)
>   {
>       ASSERT(tn < HPET_TIMER_NUM);
>       ASSERT(spin_is_locked(&h->lock));
> +    TRACE_1D(TRC_HVM_VCHIP_HPET_STOP_TIMER, tn);
>       destroy_periodic_time(&h->pt[tn]);
>       /* read the comparator to get it updated so a read while stopped will
>        * return the expected value. */
> @@ -255,6 +257,9 @@ static void hpet_set_timer(HPETState *h, unsigned int tn)
>        * being enabled (now).
>        */
>       oneshot = !timer_is_periodic(h, tn);
> +    TRACE_4D(TRC_HVM_VCHIP_HPET_START_TIMER, tn, irq,
> +             hpet_tick_to_ns(h, diff),

This will only be 32 bits wide; is there ever any risk that this may 
exceed 4 seconds (4 billion nanoseconds)?


> diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
> index e2f60a6..410f0fe 100644
> --- a/xen/include/public/trace.h
> +++ b/xen/include/public/trace.h
> @@ -52,6 +52,7 @@
>   /* trace subclasses for SVM */
>   #define TRC_HVM_ENTRYEXIT 0x00081000   /* VMENTRY and #VMEXIT       */
>   #define TRC_HVM_HANDLER   0x00082000   /* various HVM handlers      */
> +#define TRC_HVM_VCHIP     0x00084000   /* virtual chips */

Maybe TRC_HVM_EMUL, for emulated devices?

  -George

Re: [PATCH v2 2/2] xentrace: Add TRC_HVM_VCHIP

[Don Slutz]

On 04/01/14 09:23, George Dunlap wrote:
> On 03/28/2014 04:56 PM, Don Slutz wrote:
>> This add a set of trace events that track the setup of various
>> virtual chips related to timers in domU.

[snip]

>> @@ -255,6 +257,9 @@ static void hpet_set_timer(HPETState *h, unsigned int tn)
>>        * being enabled (now).
>>        */
>>       oneshot = !timer_is_periodic(h, tn);
>> +    TRACE_4D(TRC_HVM_VCHIP_HPET_START_TIMER, tn, irq,
>> +             hpet_tick_to_ns(h, diff),
>
> This will only be 32 bits wide; is there ever any risk that this may exceed 4 seconds (4 billion nanoseconds)?
>

Yes.  Will change to pass these all as 2 values.  I see no reason to set TRC_64_FLAG since these will allways be 64 bit values.

Will also see about using TRC_PAR_LONG(). And switch to hex in formats.

>
>> diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
>> index e2f60a6..410f0fe 100644
>> --- a/xen/include/public/trace.h
>> +++ b/xen/include/public/trace.h
>> @@ -52,6 +52,7 @@
>>   /* trace subclasses for SVM */
>>   #define TRC_HVM_ENTRYEXIT 0x00081000   /* VMENTRY and #VMEXIT       */
>>   #define TRC_HVM_HANDLER   0x00082000   /* various HVM handlers      */
>> +#define TRC_HVM_VCHIP     0x00084000   /* virtual chips */
>
> Maybe TRC_HVM_EMUL, for emulated devices?
>

That would be fine with me.  Just going to wait to see if any other comments on the name.

    -Don Slutz

>  -George
>

Re: [PATCH v2 2/2] xentrace: Add TRC_HVM_VCHIP

[Tim Deegan]

At 12:56 -0400 on 28 Mar (1396007767), Don Slutz wrote:
> This add a set of trace events that track the setup of various
> virtual chips related to timers in domU.
> 
> This set is hpet, pit (i8253, i8254), rtc (MC146818), apic (lapic),
> and pic (i8259).  The pmtimer is not traced since it does not have a
> changeable rate.
> 
> Signed-off-by: Don Slutz <dslutz@verizon.com>

Reviewed-by: Tim Deegan <tim@xen.org>

(and you can keep that reviewed-by after the changes that George suggested.)

Tim.

Re: [PATCH v2 0/2] xentrace: Add TRC_HVM_VCHIP (was xentrace: Add TRC_HW_VCHIP).

[George Dunlap]

On 03/28/2014 04:56 PM, Don Slutz wrote:
> Changes v1 to v2:
>    Tim Deegan:
>      Switch from TRC_HW_VCHIP to TRC_HVM_VCHIP.
>      Drop get_cycles()
>      Fix coding style issues.
>      Drop code that should not have been included.
>      Use names not numbers.
>
> Split in 2 patches for simpler review.
>
> Here is a subset of sample output:

Are you aware of xenalyze?  It's got a lot of advantages over 
xentrace_format; the most basic of which is that it traces vcpus as they 
run across pcpus.

hg clone http://xenbits.xenproject.org/ext/xenalyze

  -George

>
> dcs-xen-54:~/xen>grep hpet /home/don/zz-xentrace-3.out
> CPU5  841028423232 (+    3900)  hpet create [ tn = 0, irq = 0, delta = 848080, period = 1000000 ]
> CPU1  843516134148 (+   20796)  hpet destroy [ tn = 0 ]
> CPU7  846913412784 (+   26184)  hpet destroy [ tn = 0 ]
> CPU7  846913416102 (+    1776)  hpet create [ tn = 0, irq = 0, delta = 4170764048, period = 0 ]
> CPU4  851697560919 (+   11499)  hpet destroy [ tn = 1 ]
> CPU4  851697562041 (+    1122)  hpet create [ tn = 1, irq = 8, delta = 15605920, period = 0 ]
> CPU4  851765523993 (+   12567)  hpet destroy [ tn = 1 ]
> CPU5  1139751965382 (+   18624)  hpet create [ tn = 1, irq = 8, delta = 15598912, period = 0 ]
> CPU5  1139789579136 (+   23088)  hpet destroy [ tn = 1 ]
> CPU5  1139789581410 (+    2274)  hpet create [ tn = 1, irq = 8, delta = 15550992, period = 0 ]
> CPU5  1139827080720 (+   24174)  hpet destroy [ tn = 1 ]
> CPU5  1139827082718 (+    1998)  hpet create [ tn = 1, irq = 8, delta = 15550912, period = 0 ]
> CPU5  1139864572410 (+   21198)  hpet destroy [ tn = 1 ]
> CPU5  1139864574390 (+    1980)  hpet create [ tn = 1, irq = 8, delta = 15554912, period = 0 ]
> CPU5  1139902073244 (+   21180)  hpet destroy [ tn = 1 ]
> CPU5  1139902075296 (+    2052)  hpet create [ tn = 1, irq = 8, delta = 15555056, period = 0 ]
> CPU5  1139939593674 (+   29112)  hpet destroy [ tn = 1 ]
> CPU5  1139939595870 (+    2196)  hpet create [ tn = 1, irq = 8, delta = 15546992, period = 0 ]
> CPU5  1139977075716 (+   21048)  hpet destroy [ tn = 1 ]
> CPU5  1139977077642 (+    1926)  hpet create [ tn = 1, irq = 8, delta = 15555104, period = 0 ]
> CPU5  1140014582832 (+   23088)  hpet destroy [ tn = 1 ]
> CPU5  1140014584950 (+    2118)  hpet create [ tn = 1, irq = 8, delta = 15552576, period = 0 ]
> CPU5  1140038873628 (+   21150)  hpet destroy [ tn = 1 ]
> CPU5  1140038875890 (+    2262)  hpet create [ tn = 1, irq = 8, delta = 21056672, period = 0 ]
> CPU5  1140039140484 (+   18348)  hpet destroy [ tn = 1 ]
> CPU6  1142224601952 (+   12486)  hpet destroy [ tn = 0 ]
>
>
>
> Don Slutz (2):
>    xentrace: Add emacs local variables
>    xentrace: Add TRC_HVM_VCHIP
>
>   tools/xentrace/formats     | 18 ++++++++++++++++++
>   xen/arch/x86/hvm/hpet.c    | 14 ++++++++++++++
>   xen/arch/x86/hvm/i8254.c   | 18 ++++++++++++++++++
>   xen/arch/x86/hvm/rtc.c     | 18 ++++++++++++++++++
>   xen/arch/x86/hvm/vlapic.c  | 25 +++++++++++++++++++++++++
>   xen/arch/x86/hvm/vpic.c    | 20 ++++++++++++++++++++
>   xen/include/public/trace.h | 20 ++++++++++++++++++++
>   7 files changed, 133 insertions(+)
>

Re: [PATCH v2 0/2] xentrace: Add TRC_HVM_VCHIP (was xentrace: Add TRC_HW_VCHIP).

[Don Slutz]

On 04/01/14 09:06, George Dunlap wrote:
> On 03/28/2014 04:56 PM, Don Slutz wrote:
>> Changes v1 to v2:
>>    Tim Deegan:
>>      Switch from TRC_HW_VCHIP to TRC_HVM_VCHIP.
>>      Drop get_cycles()
>>      Fix coding style issues.
>>      Drop code that should not have been included.
>>      Use names not numbers.
>>
>> Split in 2 patches for simpler review.
>>
>> Here is a subset of sample output:
>
> Are you aware of xenalyze?  It's got a lot of advantages over xentrace_format; the most basic of which is that it traces vcpus as they run across pcpus.
>

I have noticed that it exists.  Not sure it would help with the issue I was looking into.

I have determined that I would see:

CPU5  841028423232 (+    3900)  hpet create [ tn = 0, irq = 0, delta = 68718266336, period = 1000000 ]

If I had been able to reproduce my issue.

Do I need to make a change there also?

    -Don Slutz

> hg clone http://xenbits.xenproject.org/ext/xenalyze
>
>  -George
>
>>
>> dcs-xen-54:~/xen>grep hpet /home/don/zz-xentrace-3.out
>> CPU5  841028423232 (+    3900)  hpet create [ tn = 0, irq = 0, delta = 848080, period = 1000000 ]
>> CPU1  843516134148 (+   20796)  hpet destroy [ tn = 0 ]
>> CPU7  846913412784 (+   26184)  hpet destroy [ tn = 0 ]
>> CPU7  846913416102 (+    1776)  hpet create [ tn = 0, irq = 0, delta = 4170764048, period = 0 ]
>> CPU4  851697560919 (+   11499)  hpet destroy [ tn = 1 ]
>> CPU4  851697562041 (+    1122)  hpet create [ tn = 1, irq = 8, delta = 15605920, period = 0 ]
>> CPU4  851765523993 (+   12567)  hpet destroy [ tn = 1 ]
>> CPU5  1139751965382 (+   18624)  hpet create [ tn = 1, irq = 8, delta = 15598912, period = 0 ]
>> CPU5  1139789579136 (+   23088)  hpet destroy [ tn = 1 ]
>> CPU5  1139789581410 (+    2274)  hpet create [ tn = 1, irq = 8, delta = 15550992, period = 0 ]
>> CPU5  1139827080720 (+   24174)  hpet destroy [ tn = 1 ]
>> CPU5  1139827082718 (+    1998)  hpet create [ tn = 1, irq = 8, delta = 15550912, period = 0 ]
>> CPU5  1139864572410 (+   21198)  hpet destroy [ tn = 1 ]
>> CPU5  1139864574390 (+    1980)  hpet create [ tn = 1, irq = 8, delta = 15554912, period = 0 ]
>> CPU5  1139902073244 (+   21180)  hpet destroy [ tn = 1 ]
>> CPU5  1139902075296 (+    2052)  hpet create [ tn = 1, irq = 8, delta = 15555056, period = 0 ]
>> CPU5  1139939593674 (+   29112)  hpet destroy [ tn = 1 ]
>> CPU5  1139939595870 (+    2196)  hpet create [ tn = 1, irq = 8, delta = 15546992, period = 0 ]
>> CPU5  1139977075716 (+   21048)  hpet destroy [ tn = 1 ]
>> CPU5  1139977077642 (+    1926)  hpet create [ tn = 1, irq = 8, delta = 15555104, period = 0 ]
>> CPU5  1140014582832 (+   23088)  hpet destroy [ tn = 1 ]
>> CPU5  1140014584950 (+    2118)  hpet create [ tn = 1, irq = 8, delta = 15552576, period = 0 ]
>> CPU5  1140038873628 (+   21150)  hpet destroy [ tn = 1 ]
>> CPU5  1140038875890 (+    2262)  hpet create [ tn = 1, irq = 8, delta = 21056672, period = 0 ]
>> CPU5  1140039140484 (+   18348)  hpet destroy [ tn = 1 ]
>> CPU6  1142224601952 (+   12486)  hpet destroy [ tn = 0 ]
>>
>>
>>
>> Don Slutz (2):
>>    xentrace: Add emacs local variables
>>    xentrace: Add TRC_HVM_VCHIP
>>
>>   tools/xentrace/formats     | 18 ++++++++++++++++++
>>   xen/arch/x86/hvm/hpet.c    | 14 ++++++++++++++
>>   xen/arch/x86/hvm/i8254.c   | 18 ++++++++++++++++++
>>   xen/arch/x86/hvm/rtc.c     | 18 ++++++++++++++++++
>>   xen/arch/x86/hvm/vlapic.c  | 25 +++++++++++++++++++++++++
>>   xen/arch/x86/hvm/vpic.c    | 20 ++++++++++++++++++++
>>   xen/include/public/trace.h | 20 ++++++++++++++++++++
>>   7 files changed, 133 insertions(+)
>>
>

Re: [PATCH v2 0/2] xentrace: Add TRC_HVM_VCHIP (was xentrace: Add TRC_HW_VCHIP).

[George Dunlap]

On 04/01/2014 04:18 PM, Don Slutz wrote:
> On 04/01/14 09:06, George Dunlap wrote:
>> On 03/28/2014 04:56 PM, Don Slutz wrote:
>>> Changes v1 to v2:
>>>    Tim Deegan:
>>>      Switch from TRC_HW_VCHIP to TRC_HVM_VCHIP.
>>>      Drop get_cycles()
>>>      Fix coding style issues.
>>>      Drop code that should not have been included.
>>>      Use names not numbers.
>>>
>>> Split in 2 patches for simpler review.
>>>
>>> Here is a subset of sample output:
>>
>> Are you aware of xenalyze?  It's got a lot of advantages over
>> xentrace_format; the most basic of which is that it traces vcpus as
>> they run across pcpus.
>>
>
> I have noticed that it exists.  Not sure it would help with the issue I
> was looking into.
>
> I have determined that I would see:
>
> CPU5  841028423232 (+    3900)  hpet create [ tn = 0, irq = 0, delta =
> 68718266336, period = 1000000 ]
>
> If I had been able to reproduce my issue.

Sure; but if you ever need to track a vcpu as it moves across pcpus, or 
see how the interaction of two vcpus cause an issue that you're seeing, 
xentrace_format isn't going to help you.

Additionally, with xenalyze it's a lot easier to add ad-hoc warnings or 
statistics gathering patches.

>
> Do I need to make a change there also?

If you want to use xenalyze to analyze your traces, it would probably 
make it a lot easier. :-)  (xenalyze will dump records it doesn't 
recognize in a sort of binary format, but that's probably not what you 
want.)

As it's out-of-tree, there's certainly no *requirement* for you to make 
a change there as a follow-up to this series.

  -George