* [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
@ 2014-03-28 11:25 Don Slutz
2014-03-28 11:45 ` Jan Beulich
2014-03-28 12:04 ` Tim Deegan
0 siblings, 2 replies; 6+ messages in thread
From: Don Slutz @ 2014-03-28 11:25 UTC (permalink / raw)
To: xen-devel
Cc: Ian Campbell, Stefano Stabellini, George Dunlap, Ian Jackson,
Don Slutz, Jan Beulich
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 | 18 ++++++++++++++++++
xen/arch/x86/hvm/vpic.c | 19 +++++++++++++++++++
xen/include/public/trace.h | 22 ++++++++++++++++++++++
7 files changed, 100 insertions(+)
diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 67fd42d..e8b1607 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 ]
+
+0x00804001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet create [ began = %(1)dus, tn = %(2)d, irq = %(3)d, delta = %(4)d, period = %(5)d ]
+0x00804002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit create [ began = %(1)dus, delta = %(2)d, period = %(3)d ]
+0x00804003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtc create [ began = %(1)dus, delta = %(2)d, period = %(3)d ]
+0x00804004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic create [ began = %(1)dus, delta = %(2)d, period = %(3)d, irq = %(4)d ]
+0x00804005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet destroy [ began = %(1)dus, tn = %(2)d ]
+0x00804006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit destroy [ began = %(1)dus ]
+0x00804007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtc destroy [ began = %(1)dus ]
+0x00804008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic destroy [ began = %(1)dus ]
+0x00804009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit callback [ began = %(1)dus ]
+0x0080400a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic callback [ began = %(1)dus ]
+0x0080400b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_update_int_output [ began = %(1)dus, int_output = %(2)d, is_master = %(3)d, irq = %(4)d ]
+0x0080400c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic vcpu_kick [ began = %(1)dus, irq = %(2)d ]
+0x0080400d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) __vpic_intack [ began = %(1)dus, is_master = %(2)d, irq = %(3)d ]
+0x0080400e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_irq_positive_edge [ began = %(1)dus, irq = %(2)d ]
+0x0080400f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_irq_negative_edge [ began = %(1)dus, irq = %(2)d ]
+0x00804010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_ack_pending_irq [ began = %(1)dus, accept_pic_intr = %(2)d, int_output = %(3)d ]
+0x00804011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic_accept_pic_intr [ began = %(1)dus, i8259_target = %(2)d, accept_pic_int = %(3)d ]
diff --git a/xen/arch/x86/hvm/hpet.c b/xen/arch/x86/hvm/hpet.c
index 4324b52..5676efb 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_2D(TRC_HW_VCHIP_HPET_STOP_TIMER, get_cycles(), 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_5D(TRC_HW_VCHIP_HPET_START_TIMER, get_cycles(),
+ 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 f7493b8..57f09b3 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_1D(TRC_HW_VCHIP_8254_TIMER_CB, get_cycles());
*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_3D(TRC_HW_VCHIP_8254_START_TIMER, get_cycles(), 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_3D(TRC_HW_VCHIP_8254_START_TIMER, get_cycles(), period, 0);
create_periodic_time(v, &pit->pt0, period, 0, 0, pit_time_fired,
&pit->count_load_time[channel]);
break;
default:
+ TRACE_1D(TRC_HW_VCHIP_8254_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_8254_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_8254_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_8254_STOP_TIMER, get_cycles());
destroy_periodic_time(&pit->pt0);
}
diff --git a/xen/arch/x86/hvm/rtc.c b/xen/arch/x86/hvm/rtc.c
index 639b4c5..03307de 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_1D(TRC_HW_VCHIP_RTC_STOP_TIMER, get_cycles());
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_3D(TRC_HW_VCHIP_RTC_START_TIMER, get_cycles(), 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_1D(TRC_HW_VCHIP_RTC_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_RTC_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_RTC_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_RTC_STOP_TIMER, get_cycles());
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 bc06010..afd4d1d 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_1D(TRC_HW_VCHIP_LAPIC_TIMER_CB, get_cycles());
*(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_1D(TRC_HW_VCHIP_LAPIC_STOP_TIMER, get_cycles());
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_1D(TRC_HW_VCHIP_LAPIC_STOP_TIMER, get_cycles());
destroy_periodic_time(&vlapic->pt);
break;
}
period = ((uint64_t)APIC_BUS_CYCLE_NS *
(uint32_t)val * vlapic->hw.timer_divisor);
+ TRACE_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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_1D(TRC_HW_VCHIP_LAPIC_STOP_TIMER, get_cycles());
destroy_periodic_time(&vlapic->pt);
}
@@ -997,12 +1005,18 @@ static int __vlapic_accept_pic_intr(struct vcpu *v)
!vlapic_disabled(vlapic)) ||
/* LAPIC has LVT0 unmasked for ExtInts? */
((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_EXTINT) ||
+ /* LAPIC has LVT0 unmasked for Fixed? */
+ ((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_FIXED) ||
/* LAPIC is fully disabled? */
vlapic_hw_disabled(vlapic)));
}
int vlapic_accept_pic_intr(struct vcpu *v)
{
+ TRACE_3D(TRC_HW_VCHIP_LAPIC_PIC_INTR, get_cycles(),
+ (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 +1120,7 @@ void vlapic_reset(struct vlapic *vlapic)
vlapic_set_reg(vlapic, APIC_SPIV, 0xff);
vlapic->hw.disabled |= VLAPIC_SW_DISABLED;
+ TRACE_1D(TRC_HW_VCHIP_LAPIC_STOP_TIMER, get_cycles());
destroy_periodic_time(&vlapic->pt);
}
@@ -1129,6 +1144,8 @@ static void lapic_rearm(struct vlapic *s)
period = ((uint64_t)APIC_BUS_CYCLE_NS *
(uint32_t)tmict * s->hw.timer_divisor);
+ TRACE_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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 +1292,7 @@ void vlapic_destroy(struct vcpu *v)
struct vlapic *vlapic = vcpu_vlapic(v);
tasklet_kill(&vlapic->init_sipi.tasklet);
+ TRACE_1D(TRC_HW_VCHIP_LAPIC_STOP_TIMER, get_cycles());
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 fea3f68..3468ab5 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,7 @@ static void vpic_update_int_output(struct hvm_hw_vpic *vpic)
ASSERT(vpic_is_locked(vpic));
irq = vpic_get_highest_priority_irq(vpic);
+ TRACE_4D(TRC_HW_VCHIP_8259_INT_OUTPUT, get_cycles(), vpic->int_output, vpic->is_master, irq);
if ( vpic->int_output == (irq >= 0) )
return;
@@ -112,7 +114,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_2D(TRC_HW_VCHIP_8259_KICK, get_cycles(), irq);
vcpu_kick(v);
+ }
}
else
{
@@ -135,6 +140,7 @@ static void __vpic_intack(struct hvm_hw_vpic *vpic, int irq)
ASSERT(vpic_is_locked(vpic));
+ TRACE_3D(TRC_HW_VCHIP_8259_INTACK, get_cycles(), vpic->is_master, irq);
/* Edge-triggered: clear the IRR (forget the edge). */
if ( !(vpic->elcr & mask) )
vpic->irr &= ~mask;
@@ -434,6 +440,7 @@ void vpic_irq_positive_edge(struct domain *d, int irq)
ASSERT(irq <= 15);
ASSERT(vpic_is_locked(vpic));
+ TRACE_2D(TRC_HW_VCHIP_8259_POSEDGE, get_cycles(), irq);
if ( irq == 2 )
return;
@@ -450,6 +457,7 @@ void vpic_irq_negative_edge(struct domain *d, int irq)
ASSERT(irq <= 15);
ASSERT(vpic_is_locked(vpic));
+ TRACE_2D(TRC_HW_VCHIP_8259_NEGEDGE, get_cycles(), irq);
if ( irq == 2 )
return;
@@ -463,6 +471,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_3D(TRC_HW_VCHIP_8259_PEND_IRQ_CALL, get_cycles(),
+ vlapic_accept_pic_intr(v), vpic->int_output);
if ( !vlapic_accept_pic_intr(v) || !vpic->int_output )
return -1;
@@ -473,3 +483,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:
+ */
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index e2f60a6..e6f25f6 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -86,6 +86,7 @@
/* Trace classes for Hardware */
#define TRC_HW_PM 0x00801000 /* Power management traces */
#define TRC_HW_IRQ 0x00802000 /* Traces relating to the handling of IRQs */
+#define TRC_HW_VCHIP 0x00804000 /* Traces relating to the handling of virtual chips */
/* Trace events per class */
#define TRC_LOST_RECORDS (TRC_GEN + 1)
@@ -244,6 +245,27 @@
#define TRC_HW_IRQ_UNMAPPED_VECTOR (TRC_HW_IRQ + 0x7)
#define TRC_HW_IRQ_HANDLED (TRC_HW_IRQ + 0x8)
+/* Trace events for virtual chips */
+#define TRC_HW_VCHIP_HPET_START_TIMER (TRC_HW_VCHIP + 0x1)
+#define TRC_HW_VCHIP_8254_START_TIMER (TRC_HW_VCHIP + 0x2)
+#define TRC_HW_VCHIP_RTC_START_TIMER (TRC_HW_VCHIP + 0x3)
+#define TRC_HW_VCHIP_LAPIC_START_TIMER (TRC_HW_VCHIP + 0x4)
+#define TRC_HW_VCHIP_HPET_STOP_TIMER (TRC_HW_VCHIP + 0x5)
+#define TRC_HW_VCHIP_8254_STOP_TIMER (TRC_HW_VCHIP + 0x6)
+#define TRC_HW_VCHIP_RTC_STOP_TIMER (TRC_HW_VCHIP + 0x7)
+#define TRC_HW_VCHIP_LAPIC_STOP_TIMER (TRC_HW_VCHIP + 0x8)
+#define TRC_HW_VCHIP_8254_TIMER_CB (TRC_HW_VCHIP + 0x9)
+#define TRC_HW_VCHIP_LAPIC_TIMER_CB (TRC_HW_VCHIP + 0xA)
+#define TRC_HW_VCHIP_8259_INT_OUTPUT (TRC_HW_VCHIP + 0xB)
+#define TRC_HW_VCHIP_8259_KICK (TRC_HW_VCHIP + 0xC)
+#define TRC_HW_VCHIP_8259_INTACK (TRC_HW_VCHIP + 0xD)
+#define TRC_HW_VCHIP_8259_POSEDGE (TRC_HW_VCHIP + 0xE)
+#define TRC_HW_VCHIP_8259_NEGEDGE (TRC_HW_VCHIP + 0xF)
+#define TRC_HW_VCHIP_8259_PEND_IRQ_CALL (TRC_HW_VCHIP + 0x10)
+#define TRC_HW_VCHIP_LAPIC_PIC_INTR (TRC_HW_VCHIP + 0x11)
+
+
+
/*
* Event Flags
*
--
1.8.4
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
2014-03-28 11:25 [PATCH 1/1] xentrace: Add TRC_HW_VCHIP Don Slutz
@ 2014-03-28 11:45 ` Jan Beulich
2014-03-28 13:18 ` Don Slutz
2014-03-28 12:04 ` Tim Deegan
1 sibling, 1 reply; 6+ messages in thread
From: Jan Beulich @ 2014-03-28 11:45 UTC (permalink / raw)
To: Don Slutz
Cc: George Dunlap, xen-devel, Ian Jackson, Ian Campbell,
Stefano Stabellini
>>> On 28.03.14 at 12:25, <dslutz@verizon.com> 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.
But you're not saying anything about why this would be useful
(considering that it wasn't needed before), and hence don't
provide a reason for taking this change.
Jan
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
2014-03-28 11:45 ` Jan Beulich
@ 2014-03-28 13:18 ` Don Slutz
2014-03-28 13:24 ` Jan Beulich
0 siblings, 1 reply; 6+ messages in thread
From: Don Slutz @ 2014-03-28 13:18 UTC (permalink / raw)
To: Jan Beulich
Cc: Ian Campbell, Stefano Stabellini, George Dunlap, Ian Jackson,
Don Slutz, xen-devel
On 03/28/14 07:45, Jan Beulich wrote:
>>>> On 28.03.14 at 12:25, <dslutz@verizon.com> 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.
> But you're not saying anything about why this would be useful
> (considering that it wasn't needed before), and hence don't
> provide a reason for taking this change.
Thank you for asking. I am assuming from this that some
patches (like this one) should have this.
This is an area that I am very weak on. No simple statement
comes to mind. So here is the story of how this patch came
about.
Months ago, 1 server for about 2 to 3 days would after 1st boot
have the 1 domU hang (1 out of 10 times) with the 1st interesting
message on the domU console of:
..MP-BIOS bug: 8254 timer not connected to IO-APIC
Since I know that this message was added to deal with certain
bad motherboards and that xen does not have this issue, I
started looking into this.
I considered add code like:
HVM_DBG_LOG(DBG_LEVEL_VLAPIC_TIMER, "value[0x%016"PRIx64"]",
value);
but was not sure this would not change the timer enough to
stop the bug from happening. So I added this patch.
I then spent a lot of time trying to reproduce this issue. I was
not able to, nor was the person and server that reported it was
able to. This was under various configurations:
1) No change.
2) debug=y xen build
3) debug=n + patch
4) debug=y + patch
Using a few of the trace files and the source code of the domU's
kernel, I was able to determine that the hpet.c code was involved.
Using this knowledge, I made a patch to xen to simulate various
values of "diff" (tn_cmp - cur_tick). With this debug code I was able
to generate the hang on demand. This work is what caused me to
post the patch:
hpet: Act more like real hardware
http://lists.xen.org/archives/html/xen-devel/2014-02/msg02408.html
Which I now know to not be complete. More testing after that time
has shown that 'diff > 0' will also cause this report if diff is large
enough. Armed with this I went back to a few saved traces that I
had an was able to determine that the first interval in the calls to
create_periodic_time() (i.e. diff) had a very high variance. I no
longer have the actual data, but my memory was that the
hpet_tick_to_ns(h, diff) values ranged from 23,696ns to 955,456ns.
More looking into linux in this area and learning about hpet hardware
and specification leads me to fact that this should not be happening.
I am still working on the set of changes to the hpet.c code to fix the
set of bugs that I think are there.
So I only know that this patch did provide very useful data to me. I
would think that it would be a help to developers in the future.
I think would could write a complex analysis program of the current
trace data and infer what some of the trace data was. This to me is
a lot harder. Since this is a new independent selectable trace a
developer can deside to include of exclude these.
This is long (and not a good reason for taking this change) but I
hope it helps.
-Don Slutz
> Jan
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
2014-03-28 11:25 [PATCH 1/1] xentrace: Add TRC_HW_VCHIP Don Slutz
2014-03-28 11:45 ` Jan Beulich
@ 2014-03-28 12:04 ` Tim Deegan
2014-03-28 13:49 ` Don Slutz
1 sibling, 1 reply; 6+ messages in thread
From: Tim Deegan @ 2014-03-28 12:04 UTC (permalink / raw)
To: Don Slutz
Cc: Ian Campbell, Stefano Stabellini, George Dunlap, Ian Jackson,
xen-devel, Jan Beulich
At 07:25 -0400 on 28 Mar (1395987951), 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>
Seems like a good idea; thanks for the patch. A few comments:
You include get_cycles() in a lot of places, but AIUI the TRACE_*D
macros already included the TSC in the trace record.
> @@ -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_3D(TRC_HW_VCHIP_RTC_START_TIMER, get_cycles(), delta, period);
Please linewrap to <80 characters.
> @@ -950,6 +955,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value)
>
> vlapic->hw.tdt_msr = value;
> /* .... reprogram tdt timer */
> + TRACE_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 0, 0, vlapic->pt.irq);
> create_periodic_time(v, &vlapic->pt, 0, 0,
> vlapic->pt.irq, vlapic_tdt_pt_cb,
> &vlapic->timer_last_update);
Likewise here (and anywhere else).
> @@ -997,12 +1005,18 @@ static int __vlapic_accept_pic_intr(struct vcpu *v)
> !vlapic_disabled(vlapic)) ||
> /* LAPIC has LVT0 unmasked for ExtInts? */
> ((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_EXTINT) ||
> + /* LAPIC has LVT0 unmasked for Fixed? */
> + ((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_FIXED) ||
What on earth is this doing here?
> diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
> index e2f60a6..e6f25f6 100644
> --- a/xen/include/public/trace.h
> +++ b/xen/include/public/trace.h
> @@ -86,6 +86,7 @@
> /* Trace classes for Hardware */
> #define TRC_HW_PM 0x00801000 /* Power management traces */
> #define TRC_HW_IRQ 0x00802000 /* Traces relating to the handling of IRQs */
> +#define TRC_HW_VCHIP 0x00804000 /* Traces relating to the handling of virtual chips */
I think most of these belong under TRC_HVM, with the other emulated
hardware. But I guess we might see PIT traces for PV guests? In that
case, maybe the timers could have a new class like like TRC_VTIMER.
In any case, please avoid _HW_, which is used elsewhere for _real_
hardware events.
> /* Trace events per class */
> #define TRC_LOST_RECORDS (TRC_GEN + 1)
> @@ -244,6 +245,27 @@
> #define TRC_HW_IRQ_UNMAPPED_VECTOR (TRC_HW_IRQ + 0x7)
> #define TRC_HW_IRQ_HANDLED (TRC_HW_IRQ + 0x8)
>
> +/* Trace events for virtual chips */
> +#define TRC_HW_VCHIP_HPET_START_TIMER (TRC_HW_VCHIP + 0x1)
> +#define TRC_HW_VCHIP_8254_START_TIMER (TRC_HW_VCHIP + 0x2)
Can you use _PIT_ for those of us who don't always remember the old
Intel part numbers?
> +#define TRC_HW_VCHIP_RTC_START_TIMER (TRC_HW_VCHIP + 0x3)
> +#define TRC_HW_VCHIP_LAPIC_START_TIMER (TRC_HW_VCHIP + 0x4)
> +#define TRC_HW_VCHIP_HPET_STOP_TIMER (TRC_HW_VCHIP + 0x5)
> +#define TRC_HW_VCHIP_8254_STOP_TIMER (TRC_HW_VCHIP + 0x6)
> +#define TRC_HW_VCHIP_RTC_STOP_TIMER (TRC_HW_VCHIP + 0x7)
> +#define TRC_HW_VCHIP_LAPIC_STOP_TIMER (TRC_HW_VCHIP + 0x8)
> +#define TRC_HW_VCHIP_8254_TIMER_CB (TRC_HW_VCHIP + 0x9)
> +#define TRC_HW_VCHIP_LAPIC_TIMER_CB (TRC_HW_VCHIP + 0xA)
> +#define TRC_HW_VCHIP_8259_INT_OUTPUT (TRC_HW_VCHIP + 0xB)
Likewise, _PIC_ would be better.
Cheers,
Tim.
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
2014-03-28 12:04 ` Tim Deegan
@ 2014-03-28 13:49 ` Don Slutz
0 siblings, 0 replies; 6+ messages in thread
From: Don Slutz @ 2014-03-28 13:49 UTC (permalink / raw)
To: Tim Deegan
Cc: Ian Campbell, Stefano Stabellini, George Dunlap, Ian Jackson,
Don Slutz, xen-devel, Jan Beulich
On 03/28/14 08:04, Tim Deegan wrote:
> At 07:25 -0400 on 28 Mar (1395987951), 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>
> Seems like a good idea; thanks for the patch. A few comments:
>
> You include get_cycles() in a lot of places, but AIUI the TRACE_*D
> macros already included the TSC in the trace record.
It should be all. I see that now. I have followed:
TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles());
and I did like seeing the ns value in the output. I will remove for the
next version.
>
>> @@ -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_3D(TRC_HW_VCHIP_RTC_START_TIMER, get_cycles(), delta, period);
> Please linewrap to <80 characters.
Will do.
>
>> @@ -950,6 +955,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value)
>>
>> vlapic->hw.tdt_msr = value;
>> /* .... reprogram tdt timer */
>> + TRACE_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 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_4D(TRC_HW_VCHIP_LAPIC_START_TIMER, get_cycles(), 0, 0, vlapic->pt.irq);
>> create_periodic_time(v, &vlapic->pt, 0, 0,
>> vlapic->pt.irq, vlapic_tdt_pt_cb,
>> &vlapic->timer_last_update);
> Likewise here (and anywhere else).
I will check them all.
>
>> @@ -997,12 +1005,18 @@ static int __vlapic_accept_pic_intr(struct vcpu *v)
>> !vlapic_disabled(vlapic)) ||
>> /* LAPIC has LVT0 unmasked for ExtInts? */
>> ((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_EXTINT) ||
>> + /* LAPIC has LVT0 unmasked for Fixed? */
>> + ((lvt0 & (APIC_MODE_MASK|APIC_LVT_MASKED)) == APIC_DM_FIXED) ||
> What on earth is this doing here?
Opps, this was testing code that I missed catching. Will just remove.
>> diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
>> index e2f60a6..e6f25f6 100644
>> --- a/xen/include/public/trace.h
>> +++ b/xen/include/public/trace.h
>> @@ -86,6 +86,7 @@
>> /* Trace classes for Hardware */
>> #define TRC_HW_PM 0x00801000 /* Power management traces */
>> #define TRC_HW_IRQ 0x00802000 /* Traces relating to the handling of IRQs */
>> +#define TRC_HW_VCHIP 0x00804000 /* Traces relating to the handling of virtual chips */
> I think most of these belong under TRC_HVM, with the other emulated
> hardware. But I guess we might see PIT traces for PV guests? In that
> case, maybe the timers could have a new class like like TRC_VTIMER.
I am not sure. Since the files changed are all in hvm, I would not
expect them for PV. They may exist for PVH.
It could, but a sub class should be good enough. Will switch to
#define TRC_HVM 0x0008f000 /* Xen HVM trace */
> In any case, please avoid _HW_, which is used elsewhere for _real_
> hardware events.
Opps, my bad.
>> /* Trace events per class */
>> #define TRC_LOST_RECORDS (TRC_GEN + 1)
>> @@ -244,6 +245,27 @@
>> #define TRC_HW_IRQ_UNMAPPED_VECTOR (TRC_HW_IRQ + 0x7)
>> #define TRC_HW_IRQ_HANDLED (TRC_HW_IRQ + 0x8)
>>
>> +/* Trace events for virtual chips */
>> +#define TRC_HW_VCHIP_HPET_START_TIMER (TRC_HW_VCHIP + 0x1)
>> +#define TRC_HW_VCHIP_8254_START_TIMER (TRC_HW_VCHIP + 0x2)
> Can you use _PIT_ for those of us who don't always remember the old
> Intel part numbers?
Sure, I was just follow the file names.
>> +#define TRC_HW_VCHIP_RTC_START_TIMER (TRC_HW_VCHIP + 0x3)
>> +#define TRC_HW_VCHIP_LAPIC_START_TIMER (TRC_HW_VCHIP + 0x4)
>> +#define TRC_HW_VCHIP_HPET_STOP_TIMER (TRC_HW_VCHIP + 0x5)
>> +#define TRC_HW_VCHIP_8254_STOP_TIMER (TRC_HW_VCHIP + 0x6)
>> +#define TRC_HW_VCHIP_RTC_STOP_TIMER (TRC_HW_VCHIP + 0x7)
>> +#define TRC_HW_VCHIP_LAPIC_STOP_TIMER (TRC_HW_VCHIP + 0x8)
>> +#define TRC_HW_VCHIP_8254_TIMER_CB (TRC_HW_VCHIP + 0x9)
>> +#define TRC_HW_VCHIP_LAPIC_TIMER_CB (TRC_HW_VCHIP + 0xA)
>> +#define TRC_HW_VCHIP_8259_INT_OUTPUT (TRC_HW_VCHIP + 0xB)
> Likewise, _PIC_ would be better.
Will do.
-Don Slutz
> Cheers,
>
> Tim.
>
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2014-03-28 13:49 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-03-28 11:25 [PATCH 1/1] xentrace: Add TRC_HW_VCHIP Don Slutz
2014-03-28 11:45 ` Jan Beulich
2014-03-28 13:18 ` Don Slutz
2014-03-28 13:24 ` Jan Beulich
2014-03-28 12:04 ` Tim Deegan
2014-03-28 13:49 ` Don Slutz
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.