|
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [Xen-devel] [PATCH 1/1] xentrace: Add TRC_HW_VCHIP
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@xxxxxxxxxxx>
---
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
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel
|
 |
Lists.xenproject.org is hosted with RackSpace, monitoring our |