diff --git a/tools/xentrace/formats b/tools/xentrace/formats index 67fd42d807..da658bf68c 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 = 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 ] +0x00084003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtc create [ delta = 0x%(1)016x , period = 0x%(2)016x ] +0x00084004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic create [ delta = 0x%(2)08x%(1)08x , period = 0x%(4)08x%(3)08x, irq = %(5)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 e1e769a02f..42c93f3b5d 100644 --- a/xen/arch/x86/hvm/hpet.c +++ b/xen/arch/x86/hvm/hpet.c @@ -20,10 +20,12 @@ #include #include #include +#include #include #include #include #include +#include #define domain_vhpet(x) (&(x)->arch.hvm_domain.pl_time.vhpet) #define vcpu_vhpet(x) (domain_vhpet((x)->domain)) @@ -191,6 +193,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_EMUL_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 +258,10 @@ static void hpet_set_timer(HPETState *h, unsigned int tn) * being enabled (now). */ oneshot = !timer_is_periodic(h, tn); + TRACE_2_LONG_4D(TRC_HVM_EMUL_HPET_START_TIMER, tn, irq, + TRC_PAR_LONG(hpet_tick_to_ns(h, diff)), + TRC_PAR_LONG(oneshot ? 0LL : + 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 6e66b49ead..c4f752734f 100644 --- a/xen/arch/x86/hvm/i8254.c +++ b/xen/arch/x86/hvm/i8254.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include #include @@ -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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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 7cd0cf453f..3fab660a7d 100644 --- a/xen/arch/x86/hvm/rtc.c +++ b/xen/arch/x86/hvm/rtc.c @@ -27,6 +27,7 @@ #include #include #include +#include #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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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 fc307c0fc5..cd7e87241d 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_EMUL_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_EMUL_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,16 @@ static int vlapic_reg_write(struct vcpu *v, vlapic_set_reg(vlapic, APIC_TMICT, val); if ( val == 0 ) { + TRACE_0D(TRC_HVM_EMUL_LAPIC_STOP_TIMER); destroy_periodic_time(&vlapic->pt); break; } period = ((uint64_t)APIC_BUS_CYCLE_NS * (uint32_t)val * vlapic->hw.timer_divisor); + TRACE_2_LONG_3D(TRC_HVM_EMUL_LAPIC_START_TIMER, TRC_PAR_LONG(period), + TRC_PAR_LONG(vlapic_lvtt_period(vlapic) ? period : 0LL), + vlapic->pt.irq); create_periodic_time(current, &vlapic->pt, period, vlapic_lvtt_period(vlapic) ? period : 0, vlapic->pt.irq, @@ -950,6 +956,8 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value) vlapic->hw.tdt_msr = value; /* .... reprogram tdt timer */ + TRACE_2_LONG_3D(TRC_HVM_EMUL_LAPIC_START_TIMER, TRC_PAR_LONG(delta), + TRC_PAR_LONG(0LL), vlapic->pt.irq); create_periodic_time(v, &vlapic->pt, delta, 0, vlapic->pt.irq, vlapic_tdt_pt_cb, &vlapic->timer_last_update); @@ -962,6 +970,8 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value) /* trigger a timer event if needed */ if ( value > 0 ) { + TRACE_2_LONG_3D(TRC_HVM_EMUL_LAPIC_START_TIMER, TRC_PAR_LONG(0LL), + TRC_PAR_LONG(0LL), vlapic->pt.irq); create_periodic_time(v, &vlapic->pt, 0, 0, vlapic->pt.irq, vlapic_tdt_pt_cb, &vlapic->timer_last_update); @@ -970,6 +980,7 @@ void vlapic_tdt_msr_set(struct vlapic *vlapic, uint64_t value) else { /* .... stop tdt timer */ + TRACE_0D(TRC_HVM_EMUL_LAPIC_STOP_TIMER); destroy_periodic_time(&vlapic->pt); } @@ -1003,6 +1014,10 @@ static int __vlapic_accept_pic_intr(struct vcpu *v) int vlapic_accept_pic_intr(struct vcpu *v) { + TRACE_2D(TRC_HVM_EMUL_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 +1121,7 @@ void vlapic_reset(struct vlapic *vlapic) vlapic_set_reg(vlapic, APIC_SPIV, 0xff); vlapic->hw.disabled |= VLAPIC_SW_DISABLED; + TRACE_0D(TRC_HVM_EMUL_LAPIC_STOP_TIMER); destroy_periodic_time(&vlapic->pt); } @@ -1129,6 +1145,8 @@ static void lapic_rearm(struct vlapic *s) period = ((uint64_t)APIC_BUS_CYCLE_NS * (uint32_t)tmict * s->hw.timer_divisor); + TRACE_2_LONG_3D(TRC_HVM_EMUL_LAPIC_START_TIMER, TRC_PAR_LONG(period), + TRC_PAR_LONG(vlapic_lvtt_period(s) ? period : 0LL), s->pt.irq); create_periodic_time(vlapic_vcpu(s), &s->pt, period, vlapic_lvtt_period(s) ? period : 0, s->pt.irq, @@ -1275,6 +1293,7 @@ void vlapic_destroy(struct vcpu *v) struct vlapic *vlapic = vcpu_vlapic(v); tasklet_kill(&vlapic->init_sipi.tasklet); + TRACE_0D(TRC_HVM_EMUL_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 5ca513cd3c..2c6e6e5f3f 100644 --- a/xen/arch/x86/hvm/vpic.c +++ b/xen/arch/x86/hvm/vpic.c @@ -30,6 +30,7 @@ #include #include #include +#include #include #include #include @@ -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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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_EMUL_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/asm-x86/hvm/trace.h b/xen/include/asm-x86/hvm/trace.h index 9d7e00b6d3..de802a6771 100644 --- a/xen/include/asm-x86/hvm/trace.h +++ b/xen/include/asm-x86/hvm/trace.h @@ -58,6 +58,13 @@ #define TRC_PAR_LONG(par) ((par)&0xFFFFFFFF),((par)>>32) +#define TRACE_2_LONG_2D(_e, d1, d2, ...) \ + TRACE_4D(_e, d1, d2) +#define TRACE_2_LONG_3D(_e, d1, d2, d3, ...) \ + TRACE_5D(_e, d1, d2, d3) +#define TRACE_2_LONG_4D(_e, d1, d2, d3, d4, ...) \ + TRACE_6D(_e, d1, d2, d3, d4) + #define HVMTRACE_ND(evt, modifier, cycles, count, d1, d2, d3, d4, d5, d6) \ do { \ if ( unlikely(tb_init_done) && DO_TRC_HVM_ ## evt ) \ diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h index e2f60a6324..cfcf4aa5ce 100644 --- a/xen/include/public/trace.h +++ b/xen/include/public/trace.h @@ -50,8 +50,9 @@ #define TRC_SUBCLS_SHIFT 12 /* trace subclasses for SVM */ -#define TRC_HVM_ENTRYEXIT 0x00081000 /* VMENTRY and #VMEXIT */ -#define TRC_HVM_HANDLER 0x00082000 /* various HVM handlers */ +#define TRC_HVM_ENTRYEXIT 0x00081000 /* VMENTRY and #VMEXIT */ +#define TRC_HVM_HANDLER 0x00082000 /* various HVM handlers */ +#define TRC_HVM_EMUL 0x00084000 /* emulated devices */ #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 emulated devices */ +#define TRC_HVM_EMUL_HPET_START_TIMER (TRC_HVM_EMUL + 0x1) +#define TRC_HVM_EMUL_PIT_START_TIMER (TRC_HVM_EMUL + 0x2) +#define TRC_HVM_EMUL_RTC_START_TIMER (TRC_HVM_EMUL + 0x3) +#define TRC_HVM_EMUL_LAPIC_START_TIMER (TRC_HVM_EMUL + 0x4) +#define TRC_HVM_EMUL_HPET_STOP_TIMER (TRC_HVM_EMUL + 0x5) +#define TRC_HVM_EMUL_PIT_STOP_TIMER (TRC_HVM_EMUL + 0x6) +#define TRC_HVM_EMUL_RTC_STOP_TIMER (TRC_HVM_EMUL + 0x7) +#define TRC_HVM_EMUL_LAPIC_STOP_TIMER (TRC_HVM_EMUL + 0x8) +#define TRC_HVM_EMUL_PIT_TIMER_CB (TRC_HVM_EMUL + 0x9) +#define TRC_HVM_EMUL_LAPIC_TIMER_CB (TRC_HVM_EMUL + 0xA) +#define TRC_HVM_EMUL_PIC_INT_OUTPUT (TRC_HVM_EMUL + 0xB) +#define TRC_HVM_EMUL_PIC_KICK (TRC_HVM_EMUL + 0xC) +#define TRC_HVM_EMUL_PIC_INTACK (TRC_HVM_EMUL + 0xD) +#define TRC_HVM_EMUL_PIC_POSEDGE (TRC_HVM_EMUL + 0xE) +#define TRC_HVM_EMUL_PIC_NEGEDGE (TRC_HVM_EMUL + 0xF) +#define TRC_HVM_EMUL_PIC_PEND_IRQ_CALL (TRC_HVM_EMUL + 0x10) +#define TRC_HVM_EMUL_LAPIC_PIC_INTR (TRC_HVM_EMUL + 0x11) + /* trace events for per class */ #define TRC_PM_FREQ_CHANGE (TRC_HW_PM + 0x01) #define TRC_PM_IDLE_ENTRY (TRC_HW_PM + 0x02)