# HG changeset patch # User Thomas Friebel # Date 1172494345 -3600 # Node ID 58d3f1c6183bdc71180446b2ee9a8218a5996e55 # Parent 2d3ceb082114bdc77e53b5710a076a1827254710 [xentrace][HVM] introduce HVM tracing to unify SVM and VMX tracing * new tracing class TRC_HVM replacing TRC_VMX * 20 new trace events to differentiate the information carried by them ** added corresponding trace points in SVM and VMX code ** updated formats file: descriptive formatting of trace event data ** completely replacing previous simple tracing in VMX * possibility to toggle single events on and off at compile time in include/asm-x86/hvm/trace.h Signed-off-by: Thomas Friebel diff -r 2d3ceb082114 -r 58d3f1c6183b tools/xentrace/formats --- a/tools/xentrace/formats Mon Feb 26 09:13:50 2007 +0000 +++ b/tools/xentrace/formats Mon Feb 26 13:52:25 2007 +0100 @@ -16,29 +16,25 @@ 0x0002f00c CPU%(cpu)d %(tsc)d (+%(relt 0x0002f00c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) t_timer_fn 0x0002f00d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) dom_timer_fn -0x00080001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_VMEXIT [ domid = 0x%(1)08x, eip = 0x%(2)08x, reason = 0x%(3)08x ] -0x00084001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_INTR [ domid = 0x%(1)08x, trap = 0x%(2)08x, va = 0x%(3)08x ] - -0x00081001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_0 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_0 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_1 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_1 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_2 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_2 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_3 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_3 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_4 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_4 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_5 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_5 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_6 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_6 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x - -0x00081008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT_7 0x%(1)08x 0x%(2)08x 0x%(3)08x -0x00082008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY_7 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x +0x00081001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY [ dom:vcpu = 0x%(1)08x ] +0x00081002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT [ dom:vcpu = 0x%(1)08x, rIP = 0x%(2)08x, exitcode = 0x%(3)08x ] +0x00082001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_XEN [ dom:vcpu = 0x%(1)08x, virt = 0x%(2)08x, errorcode = 0x%(3)02x ] +0x00082002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_INJECT [ dom:vcpu = 0x%(1)08x, virt = 0x%(2)08x, errorcode = 0x%(3)02x ] +0x00082003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INJ_EXC [ dom:vcpu = 0x%(1)08x, vector = 0x%(2)02x, errorcode = 0x%(3)04x ] +0x00082004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INJ_VIRQ [ dom:vcpu = 0x%(1)08x, vector = 0x%(2)02x, fake = %(3)d ] +0x00082005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) REINJ_VIRQ [ dom:vcpu = 0x%(1)08x, vector = 0x%(2)02x ] +0x00082006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IO_READ [ dom:vcpu = 0x%(1)08x, port = 0x%(2)04x, size = %(3)d ] +0x00082007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IO_WRITE [ dom:vcpu = 0x%(1)08x, port = 0x%(2)04x, size = %(3)d ] +0x00082008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_READ [ dom:vcpu = 0x%(1)08x, CR# = %(2)d, value = 0x%(3)08x ] +0x00082009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_WRITE [ dom:vcpu = 0x%(1)08x, CR# = %(2)d, value = 0x%(3)08x ] +0x0008200A CPU%(cpu)d %(tsc)d (+%(reltsc)8d) DR_READ [ dom:vcpu = 0x%(1)08x ] +0x0008200B CPU%(cpu)d %(tsc)d (+%(reltsc)8d) DR_WRITE [ dom:vcpu = 0x%(1)08x ] +0x0008200C CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MSR_READ [ dom:vcpu = 0x%(1)08x, MSR# = 0x%(2)08x, value = 0x%(3)08x ] +0x0008200D CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MSR_WRITE [ dom:vcpu = 0x%(1)08x, MSR# = 0x%(2)08x, value = 0x%(3)08x ] +0x0008200E CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CPUID [ dom:vcpu = 0x%(1)08x, func = 0x%(2)08x, eax:ebx = 0x%(3)016x, ecx:edx = 0x%(4)016x ] +0x0008200F CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INTR [ dom:vcpu = 0x%(1)08x, vector = 0x%(2)02x ] +0x00082010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) NMI [ dom:vcpu = 0x%(1)08x ] +0x00082011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SMI [ dom:vcpu = 0x%(1)08x ] +0x00082012 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMMCALL [ dom:vcpu = 0x%(1)08x, func = 0x%(2)08x ] +0x00082013 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) HLT [ dom:vcpu = 0x%(1)08x, intpending = %(2)d ] +0x00082014 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INVLPG [ dom:vcpu = 0x%(1)08x, virt = 0x%(2)08x, invlpga = %(3)d, asid = 0x%(4)02x ] diff -r 2d3ceb082114 -r 58d3f1c6183b tools/xentrace/xentrace.8 --- a/tools/xentrace/xentrace.8 Mon Feb 26 09:13:50 2007 +0000 +++ b/tools/xentrace/xentrace.8 Mon Feb 26 13:52:25 2007 +0100 @@ -1,4 +1,4 @@ -.TH XENTRACE 8 "11 March 2004" "Xen domain 0 utils" +.TH XENTRACE 8 "22 February 2007" "Xen domain 0 utils" .SH NAME xentrace \- capture Xen trace buffer data .SH SYNOPSIS @@ -59,10 +59,10 @@ gathered by xentrace: .PP 0x0001f000 TRC_GEN 0x0002f000 TRC_SCHED - 0x0004f000 TRC_DOM0OP - 0x0008f000 TRC_VMX - 0x000af000 TRC_MEM - 0xfffff000 TRC_ALL + 0x0004f000 TRC_DOM0OP + 0x0008f000 TRC_HVM + 0x0010f000 TRC_MEM + 0xfffff000 TRC_ALL .SS Event Subclasses (More Masks) @@ -71,10 +71,8 @@ gathered by xentrace: .PP \fIID\fP \fIDescription\fP .PP - 0x00081000 TRC_VMXEXIT - 0x00082000 TRC_VMXTIMER - 0x00084000 TRC_VMXINT - 0x00088000 TRC_VMXIO + 0x00081000 TRC_HVM_ENTRYEXIT + 0x00082000 TRC_HVM_HANDLER .SS Events @@ -82,7 +80,8 @@ collects the following events from the t collects the following events from the trace buffer: .PP \fIID\fP \fIDescription\fP -.PP +.PP + 0x0001f001 TRC_LOST_RECORDS 0x0002f001 TRC_SCHED_DOM_ADD 0x0002f002 TRC_SCHED_DOM_REM 0x0002f003 TRC_SCHED_SLEEP @@ -99,16 +98,33 @@ collects the following events from the t 0x0002f014 TRC_SCHED_SWITCH_INFPREV 0x0002f015 TRC_SCHED_SWITCH_INFNEXT - 0x000af001 TRC_MEM_PAGE_GRANT_MAP - 0x000af002 TRC_MEM_PAGE_GRANT_UNMAP - 0x000af003 TRC_MEM_PAGE_GRANT_TRANSFER + 0x00081001 TRC_HVM_VMENTRY + 0x00081002 TRC_HVM_VMEXIT + 0x00082001 TRC_HVM_PF_XEN + 0x00082002 TRC_HVM_PF_INJECT + 0x00082003 TRC_HVM_INJ_EXC + 0x00082004 TRC_HVM_INJ_VIRQ + 0x00082005 TRC_HVM_REINJ_VIRQ + 0x00082006 TRC_HVM_IO_READ + 0x00082007 TRC_HVM_IO_WRITE + 0x00082008 TRC_HVM_CR_READ + 0x00082009 TRC_HVM_CR_WRITE + 0x0008200A TRC_HVM_DR_READ + 0x0008200B TRC_HVM_DR_WRITE + 0x0008200C TRC_HVM_MSR_READ + 0x0008200D TRC_HVM_MSR_WRITE + 0x0008200E TRC_HVM_CPUID + 0x0008200F TRC_HVM_INTR + 0x00082010 TRC_HVM_NMI + 0x00082011 TRC_HVM_SMI + 0x00082012 TRC_HVM_VMMCALL + 0x00082013 TRC_HVM_HLT + 0x00082014 TRC_HVM_INVLPG - 0x00081001 TRC_VMX_VMEXIT - 0x00081002 TRC_VMX_VMENTRY - - 0x00082001 TRC_VMX_TIMER_INTR - - 0x00084001 TRC_VMX_INT + 0x0010f001 TRC_MEM_PAGE_GRANT_MAP + 0x0010f002 TRC_MEM_PAGE_GRANT_UNMAP + 0x0010f003 TRC_MEM_PAGE_GRANT_TRANSFER + .PP .SH AUTHOR diff -r 2d3ceb082114 -r 58d3f1c6183b tools/xentrace/xentrace.c --- a/tools/xentrace/xentrace.c Mon Feb 26 09:13:50 2007 +0000 +++ b/tools/xentrace/xentrace.c Mon Feb 26 13:52:25 2007 +0100 @@ -350,8 +350,8 @@ int parse_evtmask(char *arg, struct argp setup->evt_mask |= TRC_SCHED; } else if(strcmp(arg, "dom0op") == 0){ setup->evt_mask |= TRC_DOM0OP; - } else if(strcmp(arg, "vmx") == 0){ - setup->evt_mask |= TRC_VMX; + } else if(strcmp(arg, "hvm") == 0){ + setup->evt_mask |= TRC_HVM; } else if(strcmp(arg, "all") == 0){ setup->evt_mask |= TRC_ALL; } else { diff -r 2d3ceb082114 -r 58d3f1c6183b xen/arch/x86/hvm/io.c --- a/xen/arch/x86/hvm/io.c Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/arch/x86/hvm/io.c Mon Feb 26 13:52:25 2007 +0100 @@ -414,7 +414,6 @@ static void hvm_pio_assist(struct cpu_us printk("Error: %s unknown port size\n", __FUNCTION__); domain_crash_synchronous(); } - TRACE_VMEXIT(3, regs->eax); } } diff -r 2d3ceb082114 -r 58d3f1c6183b xen/arch/x86/hvm/svm/intr.c --- a/xen/arch/x86/hvm/svm/intr.c Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/arch/x86/hvm/svm/intr.c Mon Feb 26 13:52:25 2007 +0100 @@ -37,6 +37,7 @@ #include #include #include +#include /* * Most of this code is copied from vmx_io.c and modified @@ -108,6 +109,7 @@ asmlinkage void svm_intr_assist(void) if ( irq_masked(vmcb->rflags) || vmcb->interrupt_shadow ) { vmcb->general1_intercepts |= GENERAL1_INTERCEPT_VINTR; + HVMTRACE_2D(INJ_VIRQ, v, 0x0, /*fake=*/ 1); svm_inject_extint(v, 0x0); /* actual vector doesn't really matter */ return; } @@ -128,7 +130,10 @@ asmlinkage void svm_intr_assist(void) if ( re_injecting && (pt = is_pt_irq(v, intr_vector, intr_type)) ) ++pt->pending_intr_nr; /* let's inject this interrupt */ - TRACE_3D(TRC_VMX_INTR, v->domain->domain_id, intr_vector, 0); + if (re_injecting) + HVMTRACE_1D(REINJ_VIRQ, v, intr_vector); + else + HVMTRACE_2D(INJ_VIRQ, v, intr_vector, /*fake=*/ 0); svm_inject_extint(v, intr_vector); break; case APIC_DM_SMI: diff -r 2d3ceb082114 -r 58d3f1c6183b xen/arch/x86/hvm/svm/svm.c --- a/xen/arch/x86/hvm/svm/svm.c Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/arch/x86/hvm/svm/svm.c Mon Feb 26 13:52:25 2007 +0100 @@ -48,6 +48,7 @@ #include #include #include +#include #define SVM_EXTRA_DEBUG @@ -80,6 +81,14 @@ static inline void svm_inject_exception( { eventinj_t event; struct vmcb_struct *vmcb = v->arch.hvm_svm.vmcb; + + if (trap == TRAP_page_fault) + HVMTRACE_2D( + PF_INJECT, v, + v->arch.hvm_svm.cpu_cr2, error_code + ); + else + HVMTRACE_2D(INJ_EXC, v, trap, error_code); event.bytes = 0; event.fields.v = 1; @@ -977,9 +986,9 @@ static void svm_hvm_inject_exception( unsigned int trapnr, int errcode, unsigned long cr2) { struct vcpu *v = current; - svm_inject_exception(v, trapnr, (errcode != -1), errcode); if ( trapnr == TRAP_page_fault ) v->arch.hvm_svm.vmcb->cr2 = v->arch.hvm_svm.cpu_cr2 = cr2; + svm_inject_exception(v, trapnr, (errcode != -1), errcode); } static int svm_event_injection_faulted(struct vcpu *v) @@ -1209,6 +1218,8 @@ static void svm_vmexit_do_cpuid(struct v regs->ecx = (unsigned long)ecx; regs->edx = (unsigned long)edx; + HVMTRACE_3D(CPUID, v, input, ((unsigned long)eax<<32)+ebx, ((unsigned long)ecx<<32)+edx); + inst_len = __get_instruction_length(vmcb, INSTR_CPUID, NULL); ASSERT(inst_len > 0); __update_guest_eip(vmcb, inst_len); @@ -1299,6 +1310,8 @@ static void svm_dr_access(struct vcpu *v static void svm_dr_access(struct vcpu *v, struct cpu_user_regs *regs) { struct vmcb_struct *vmcb = v->arch.hvm_svm.vmcb; + + HVMTRACE_0D(DR_WRITE, v); v->arch.hvm_vcpu.flag_dr_dirty = 1; @@ -1579,6 +1592,11 @@ static void svm_io_instruction(struct vc else size = 1; + if (dir==IOREQ_READ) + HVMTRACE_2D(IO_READ, v, port, size); + else + HVMTRACE_2D(IO_WRITE, v, port, size); + HVM_DBG_LOG(DBG_LEVEL_IO, "svm_io_instruction: port 0x%x eip=%x:%"PRIx64", " "exit_qualification = %"PRIx64, @@ -1835,6 +1853,8 @@ static void mov_from_cr(int cr, int gp, return; } + HVMTRACE_2D(CR_READ, v, cr, value); + set_reg(gp, value, regs, vmcb); HVM_DBG_LOG(DBG_LEVEL_VMMU, "mov_from_cr: CR%d, value = %lx,", cr, value); @@ -1858,6 +1878,8 @@ static int mov_to_cr(int gpreg, int cr, struct vmcb_struct *vmcb = v->arch.hvm_svm.vmcb; value = get_reg(gpreg, regs, vmcb); + + HVMTRACE_2D(CR_WRITE, v, cr, value); HVM_DBG_LOG(DBG_LEVEL_1, "mov_to_cr: CR%d, value = %lx,", cr, value); HVM_DBG_LOG(DBG_LEVEL_1, "current = %lx,", (unsigned long) current); @@ -2152,6 +2174,7 @@ static inline void svm_do_msr_access( regs->edx = msr_content >> 32; done: + HVMTRACE_2D(MSR_READ, v, ecx, msr_content); HVM_DBG_LOG(DBG_LEVEL_1, "returns: ecx=%x, eax=%lx, edx=%lx", ecx, (unsigned long)regs->eax, (unsigned long)regs->edx); @@ -2160,6 +2183,8 @@ static inline void svm_do_msr_access( else { msr_content = (u32)regs->eax | ((u64)regs->edx << 32); + + HVMTRACE_2D(MSR_WRITE, v, ecx, msr_content); switch (ecx) { @@ -2198,9 +2223,12 @@ static inline void svm_vmexit_do_hlt(str /* Check for interrupt not handled or new interrupt. */ if ( (vmcb->rflags & X86_EFLAGS_IF) && - (vmcb->vintr.fields.irq || cpu_has_pending_irq(current)) ) + (vmcb->vintr.fields.irq || cpu_has_pending_irq(current)) ) { + HVMTRACE_1D(HLT, current, /*int pending=*/ 1); return; - + } + + HVMTRACE_1D(HLT, current, /*int pending=*/ 0); hvm_hlt(vmcb->rflags); } @@ -2311,6 +2339,8 @@ void svm_handle_invlpg(const short invlp inst_len += length; __update_guest_eip (vmcb, inst_len); } + + HVMTRACE_3D(INVLPG, v, (invlpga?1:0), g_vaddr, (invlpga?regs->ecx:0)); paging_invlpg(v, g_vaddr); } @@ -2427,6 +2457,8 @@ static int svm_do_vmmcall(struct vcpu *v inst_len = __get_instruction_length(vmcb, INSTR_VMCALL, NULL); ASSERT(inst_len > 0); + + HVMTRACE_1D(VMMCALL, v, regs->eax); if ( regs->eax & 0x80000000 ) { @@ -2732,6 +2764,8 @@ asmlinkage void svm_vmexit_handler(struc exit_reason = vmcb->exitcode; save_svm_cpu_user_regs(v, regs); + HVMTRACE_2D(VMEXIT, v, vmcb->rip, exit_reason); + if (exit_reason == VMEXIT_INVALID) { svm_dump_vmcb(__func__, vmcb); @@ -2854,8 +2888,6 @@ asmlinkage void svm_vmexit_handler(struc } #endif /* SVM_EXTRA_DEBUG */ - TRACE_3D(TRC_VMX_VMEXIT, v->domain->domain_id, eip, exit_reason); - switch (exit_reason) { case VMEXIT_EXCEPTION_DB: @@ -2872,9 +2904,16 @@ asmlinkage void svm_vmexit_handler(struc break; case VMEXIT_INTR: + /* Asynchronous event, handled when we STGI'd after the VMEXIT. */ + HVMTRACE_0D(INTR, v); + break; case VMEXIT_NMI: + /* Asynchronous event, handled when we STGI'd after the VMEXIT. */ + HVMTRACE_0D(NMI, v); + break; case VMEXIT_SMI: - /* Asynchronous events, handled when we STGI'd after the VMEXIT. */ + /* Asynchronous event, handled when we STGI'd after the VMEXIT. */ + HVMTRACE_0D(SMI, v); break; case VMEXIT_INIT: @@ -2916,14 +2955,15 @@ asmlinkage void svm_vmexit_handler(struc if (!(error = svm_do_page_fault(va, regs))) { + v->arch.hvm_svm.cpu_cr2 = va; + vmcb->cr2 = va; + /* Inject #PG using Interruption-Information Fields */ svm_inject_exception(v, TRAP_page_fault, 1, regs->error_code); - - v->arch.hvm_svm.cpu_cr2 = va; - vmcb->cr2 = va; - TRACE_3D(TRC_VMX_INTR, v->domain->domain_id, - VMEXIT_EXCEPTION_PF, va); - } + } + else + HVMTRACE_2D(PF_XEN, v, va, regs->error_code + ); break; } @@ -3060,6 +3100,9 @@ asmlinkage void svm_load_cr2(void) asmlinkage void svm_load_cr2(void) { struct vcpu *v = current; + + // this is the last C code before the VMRUN instruction + HVMTRACE_0D(VMENTRY, v); local_irq_disable(); asm volatile("mov %0,%%cr2": :"r" (v->arch.hvm_svm.cpu_cr2)); diff -r 2d3ceb082114 -r 58d3f1c6183b xen/arch/x86/hvm/vmx/intr.c --- a/xen/arch/x86/hvm/vmx/intr.c Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/arch/x86/hvm/vmx/intr.c Mon Feb 26 13:52:25 2007 +0100 @@ -37,6 +37,7 @@ #include #include #include +#include static inline void @@ -162,8 +163,8 @@ asmlinkage void vmx_intr_assist(void) case APIC_DM_EXTINT: case APIC_DM_FIXED: case APIC_DM_LOWEST: + HVMTRACE_2D(INJ_VIRQ, v, highest_vector, /*fake=*/ 0); vmx_inject_extint(v, highest_vector, VMX_DELIVER_NO_ERROR_CODE); - TRACE_3D(TRC_VMX_INTR, v->domain->domain_id, highest_vector, 0); break; case APIC_DM_SMI: diff -r 2d3ceb082114 -r 58d3f1c6183b xen/arch/x86/hvm/vmx/vmx.c --- a/xen/arch/x86/hvm/vmx/vmx.c Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/arch/x86/hvm/vmx/vmx.c Mon Feb 26 13:52:25 2007 +0100 @@ -49,6 +49,7 @@ #include #include #include +#include static void vmx_ctxt_switch_from(struct vcpu *v); static void vmx_ctxt_switch_to(struct vcpu *v); @@ -1127,7 +1128,6 @@ static int vmx_do_page_fault(unsigned lo result = paging_fault(va, regs); - TRACE_VMEXIT(2, result); #if 0 if ( !result ) { @@ -1223,6 +1223,8 @@ static void vmx_do_cpuid(struct cpu_user regs->ebx = (unsigned long)ebx; regs->ecx = (unsigned long)ecx; regs->edx = (unsigned long)edx; + + HVMTRACE_3D(CPUID, current, input, ((unsigned long)eax<<32)+ebx, ((unsigned long)ecx<<32)+edx); } #define CASE_GET_REG_P(REG, reg) \ @@ -1247,6 +1249,8 @@ static void vmx_dr_access(unsigned long { struct vcpu *v = current; + HVMTRACE_0D(DR_WRITE, v); + v->arch.hvm_vcpu.flag_dr_dirty = 1; /* We could probably be smarter about this */ @@ -1266,6 +1270,8 @@ static void vmx_do_invlpg(unsigned long { unsigned long eip; struct vcpu *v = current; + + HVMTRACE_2D(INVLPG, v, /*invlpga=*/ 0, va); eip = __vmread(GUEST_RIP); @@ -1416,10 +1422,13 @@ static void vmx_io_instruction(unsigned else port = regs->edx & 0xffff; - TRACE_VMEXIT(1, port); - size = (exit_qualification & 7) + 1; dir = test_bit(3, &exit_qualification); /* direction */ + + if (dir==IOREQ_READ) + HVMTRACE_2D(IO_READ, current, port, size); + else + HVMTRACE_2D(IO_WRITE, current, port, size); if ( test_bit(4, &exit_qualification) ) { /* string instruction */ unsigned long addr, count = 1, base; @@ -1614,9 +1623,6 @@ static void vmx_io_instruction(unsigned if ( port == 0xe9 && dir == IOREQ_WRITE && size == 1 ) hvm_print_line(current, regs->eax); /* guest debug output */ - if ( dir == IOREQ_WRITE ) - TRACE_VMEXIT(2, regs->eax); - regs->eip += inst_len; send_pio_req(port, 1, size, regs->eax, dir, df, 0); } @@ -2062,9 +2068,7 @@ static int mov_to_cr(int gp, int cr, str goto exit_and_crash; } - TRACE_VMEXIT(1, TYPE_MOV_TO_CR); - TRACE_VMEXIT(2, cr); - TRACE_VMEXIT(3, value); + HVMTRACE_2D(CR_WRITE, v, cr, value); HVM_DBG_LOG(DBG_LEVEL_1, "CR%d, value = %lx", cr, value); @@ -2231,9 +2235,7 @@ static void mov_from_cr(int cr, int gp, break; } - TRACE_VMEXIT(1, TYPE_MOV_FROM_CR); - TRACE_VMEXIT(2, cr); - TRACE_VMEXIT(3, value); + HVMTRACE_2D(CR_READ, v, cr, value); HVM_DBG_LOG(DBG_LEVEL_VMMU, "CR%d, value = %lx", cr, value); } @@ -2256,7 +2258,7 @@ static int vmx_cr_access(unsigned long e mov_from_cr(cr, gp, regs); break; case TYPE_CLTS: - TRACE_VMEXIT(1, TYPE_CLTS); +// TRACE_VMEXIT(1, TYPE_CLTS); /* We initialise the FPU now, to avoid needing another vmexit. */ setup_fpu(v); @@ -2272,8 +2274,8 @@ static int vmx_cr_access(unsigned long e value = v->arch.hvm_vmx.cpu_shadow_cr0; value = (value & ~0xF) | (((exit_qualification & LMSW_SOURCE_DATA) >> 16) & 0xF); - TRACE_VMEXIT(1, TYPE_LMSW); - TRACE_VMEXIT(2, value); +// TRACE_VMEXIT(1, TYPE_LMSW); +// TRACE_VMEXIT(2, value); return vmx_set_cr0(value); break; default: @@ -2327,6 +2329,7 @@ static inline int vmx_do_msr_read(struct regs->edx = msr_content >> 32; done: + HVMTRACE_2D(MSR_READ, v, ecx, msr_content); HVM_DBG_LOG(DBG_LEVEL_1, "returns: ecx=%x, eax=%lx, edx=%lx", ecx, (unsigned long)regs->eax, (unsigned long)regs->edx); @@ -2343,6 +2346,7 @@ static inline int vmx_do_msr_write(struc ecx, (u32)regs->eax, (u32)regs->edx); msr_content = (u32)regs->eax | ((u64)regs->edx << 32); + HVMTRACE_2D(MSR_WRITE, v, ecx, msr_content); switch (ecx) { case MSR_IA32_TIME_STAMP_COUNTER: @@ -2373,6 +2377,7 @@ static void vmx_do_hlt(void) static void vmx_do_hlt(void) { unsigned long rflags; + HVMTRACE_0D(HLT, current); rflags = __vmread(GUEST_RFLAGS); hvm_hlt(rflags); } @@ -2396,7 +2401,7 @@ static inline void vmx_do_extint(struct BUG_ON(!(vector & INTR_INFO_VALID_MASK)); vector &= INTR_INFO_VECTOR_MASK; - TRACE_VMEXIT(1, vector); + HVMTRACE_1D(INTR, current, vector); switch(vector) { case LOCAL_TIMER_VECTOR: @@ -2560,12 +2565,11 @@ asmlinkage void vmx_vmexit_handler(struc unsigned long exit_qualification, inst_len = 0; struct vcpu *v = current; - TRACE_3D(TRC_VMX_VMEXIT + v->vcpu_id, 0, 0, 0); - exit_reason = __vmread(VM_EXIT_REASON); + HVMTRACE_2D(VMEXIT, v, __vmread(GUEST_RIP), exit_reason); + perfc_incra(vmexits, exit_reason); - TRACE_VMEXIT(0, exit_reason); if ( exit_reason != EXIT_REASON_EXTERNAL_INTERRUPT ) local_irq_enable(); @@ -2589,7 +2593,6 @@ asmlinkage void vmx_vmexit_handler(struc vector = intr_info & INTR_INFO_VECTOR_MASK; - TRACE_VMEXIT(1, vector); perfc_incra(cause_vector, vector); switch ( vector ) @@ -2647,9 +2650,6 @@ asmlinkage void vmx_vmexit_handler(struc exit_qualification = __vmread(EXIT_QUALIFICATION); regs->error_code = __vmread(VM_EXIT_INTR_ERROR_CODE); - TRACE_VMEXIT(3, regs->error_code); - TRACE_VMEXIT(4, exit_qualification); - HVM_DBG_LOG(DBG_LEVEL_VMMU, "eax=%lx, ebx=%lx, ecx=%lx, edx=%lx, esi=%lx, edi=%lx", (unsigned long)regs->eax, (unsigned long)regs->ebx, @@ -2658,15 +2658,17 @@ asmlinkage void vmx_vmexit_handler(struc if ( !vmx_do_page_fault(exit_qualification, regs) ) { + v->arch.hvm_vmx.cpu_cr2 = exit_qualification; /* Inject #PG using Interruption-Information Fields. */ vmx_inject_hw_exception(v, TRAP_page_fault, regs->error_code); - v->arch.hvm_vmx.cpu_cr2 = exit_qualification; - TRACE_3D(TRC_VMX_INTR, v->domain->domain_id, - TRAP_page_fault, exit_qualification); } + else + HVMTRACE_2D(PF_XEN, v, exit_qualification, regs->error_code + ); break; } case TRAP_nmi: + HVMTRACE_0D(NMI, v); if ( (intr_info & INTR_INFO_INTR_TYPE_MASK) == INTR_TYPE_NMI ) do_nmi(regs); /* Real NMI, vector 2: normal processing. */ else @@ -2708,11 +2710,11 @@ asmlinkage void vmx_vmexit_handler(struc __update_guest_eip(inst_len); exit_qualification = __vmread(EXIT_QUALIFICATION); vmx_do_invlpg(exit_qualification); - TRACE_VMEXIT(4, exit_qualification); break; } case EXIT_REASON_VMCALL: { + HVMTRACE_1D(VMMCALL, v, regs->eax); inst_len = __get_instruction_length(); /* Safe: VMCALL */ __update_guest_eip(inst_len); hvm_do_hypercall(regs); @@ -2724,7 +2726,6 @@ asmlinkage void vmx_vmexit_handler(struc inst_len = __get_instruction_length(); /* Safe: MOV Cn, LMSW, CLTS */ if ( vmx_cr_access(exit_qualification, regs) ) __update_guest_eip(inst_len); - TRACE_VMEXIT(4, exit_qualification); break; } case EXIT_REASON_DR_ACCESS: @@ -2735,23 +2736,16 @@ asmlinkage void vmx_vmexit_handler(struc exit_qualification = __vmread(EXIT_QUALIFICATION); inst_len = __get_instruction_length(); /* Safe: IN, INS, OUT, OUTS */ vmx_io_instruction(exit_qualification, inst_len); - TRACE_VMEXIT(4, exit_qualification); break; case EXIT_REASON_MSR_READ: inst_len = __get_instruction_length(); /* Safe: RDMSR */ if ( vmx_do_msr_read(regs) ) __update_guest_eip(inst_len); - TRACE_VMEXIT(1, regs->ecx); - TRACE_VMEXIT(2, regs->eax); - TRACE_VMEXIT(3, regs->edx); break; case EXIT_REASON_MSR_WRITE: inst_len = __get_instruction_length(); /* Safe: WRMSR */ if ( vmx_do_msr_write(regs) ) __update_guest_eip(inst_len); - TRACE_VMEXIT(1, regs->ecx); - TRACE_VMEXIT(2, regs->eax); - TRACE_VMEXIT(3, regs->edx); break; case EXIT_REASON_MWAIT_INSTRUCTION: case EXIT_REASON_MONITOR_INSTRUCTION: @@ -2785,18 +2779,7 @@ asmlinkage void vmx_trace_vmentry(void) asmlinkage void vmx_trace_vmentry(void) { struct vcpu *v = current; - TRACE_5D(TRC_VMX_VMENTRY + current->vcpu_id, - v->arch.hvm_vcpu.hvm_trace_values[0], - v->arch.hvm_vcpu.hvm_trace_values[1], - v->arch.hvm_vcpu.hvm_trace_values[2], - v->arch.hvm_vcpu.hvm_trace_values[3], - v->arch.hvm_vcpu.hvm_trace_values[4]); - - TRACE_VMEXIT(0, 0); - TRACE_VMEXIT(1, 0); - TRACE_VMEXIT(2, 0); - TRACE_VMEXIT(3, 0); - TRACE_VMEXIT(4, 0); + HVMTRACE_0D(VMENTRY, v); } /* diff -r 2d3ceb082114 -r 58d3f1c6183b xen/include/asm-x86/hvm/support.h --- a/xen/include/asm-x86/hvm/support.h Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/include/asm-x86/hvm/support.h Mon Feb 26 13:52:25 2007 +0100 @@ -116,9 +116,6 @@ extern unsigned int opt_hvm_debug_level; #define HVM_DBG_LOG(level, _f, _a...) #endif -#define TRACE_VMEXIT(index, value) \ - current->arch.hvm_vcpu.hvm_trace_values[index] = (value) - /* * Save/restore support */ diff -r 2d3ceb082114 -r 58d3f1c6183b xen/include/asm-x86/hvm/vcpu.h --- a/xen/include/asm-x86/hvm/vcpu.h Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/include/asm-x86/hvm/vcpu.h Mon Feb 26 13:52:25 2007 +0100 @@ -45,8 +45,6 @@ struct hvm_vcpu { /* Flags */ int flag_dr_dirty; - unsigned long hvm_trace_values[5]; - union { struct arch_vmx_struct vmx; struct arch_svm_struct svm; diff -r 2d3ceb082114 -r 58d3f1c6183b xen/include/asm-x86/hvm/vmx/vmx.h --- a/xen/include/asm-x86/hvm/vmx/vmx.h Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/include/asm-x86/hvm/vmx/vmx.h Mon Feb 26 13:52:25 2007 +0100 @@ -25,6 +25,7 @@ #include #include #include +#include extern void vmx_asm_vmexit_handler(struct cpu_user_regs); extern void vmx_asm_do_vmentry(void); @@ -294,6 +295,11 @@ static inline void __vmx_inject_exceptio __vmwrite(VM_ENTRY_INSTRUCTION_LEN, ilen); __vmwrite(VM_ENTRY_INTR_INFO_FIELD, intr_fields); + + if (trap == TRAP_page_fault) + HVMTRACE_2D(PF_INJECT, v, v->arch.hvm_vmx.cpu_cr2, error_code); + else + HVMTRACE_2D(INJ_EXC, v, trap, error_code); } static inline void vmx_inject_hw_exception( diff -r 2d3ceb082114 -r 58d3f1c6183b xen/include/public/trace.h --- a/xen/include/public/trace.h Mon Feb 26 09:13:50 2007 +0000 +++ b/xen/include/public/trace.h Mon Feb 26 13:52:25 2007 +0100 @@ -31,17 +31,16 @@ #define TRC_GEN 0x0001f000 /* General trace */ #define TRC_SCHED 0x0002f000 /* Xen Scheduler trace */ #define TRC_DOM0OP 0x0004f000 /* Xen DOM0 operation trace */ -#define TRC_VMX 0x0008f000 /* Xen VMX trace */ +#define TRC_HVM 0x0008f000 /* Xen HVM trace */ #define TRC_MEM 0x0010f000 /* Xen memory trace */ #define TRC_ALL 0xfffff000 /* Trace subclasses */ #define TRC_SUBCLS_SHIFT 12 -/* trace subclasses for VMX */ -#define TRC_VMXEXIT 0x00081000 /* VMX exit trace */ -#define TRC_VMXENTRY 0x00082000 /* VMX exit trace */ -#define TRC_VMXINTR 0x00084000 /* VMX interrupt trace */ +/* trace subclasses for SVM */ +#define TRC_HVM_ENTRYEXIT 0x00081000 /* VMENTRY and #VMEXIT */ +#define TRC_HVM_HANDLER 0x00082000 /* various HVM handlers */ /* Trace events per class */ #define TRC_LOST_RECORDS (TRC_GEN + 1) @@ -67,10 +66,28 @@ #define TRC_MEM_PAGE_GRANT_TRANSFER (TRC_MEM + 3) /* trace events per subclass */ -#define TRC_VMX_VMEXIT (TRC_VMXEXIT + 1) -#define TRC_VMX_VMENTRY (TRC_VMXENTRY + 1) -#define TRC_VMX_INTR (TRC_VMXINTR + 1) - +#define TRC_HVM_VMENTRY (TRC_HVM_ENTRYEXIT + 0x01) +#define TRC_HVM_VMEXIT (TRC_HVM_ENTRYEXIT + 0x02) +#define TRC_HVM_PF_XEN (TRC_HVM_HANDLER + 0x01) +#define TRC_HVM_PF_INJECT (TRC_HVM_HANDLER + 0x02) +#define TRC_HVM_INJ_EXC (TRC_HVM_HANDLER + 0x03) +#define TRC_HVM_INJ_VIRQ (TRC_HVM_HANDLER + 0x04) +#define TRC_HVM_REINJ_VIRQ (TRC_HVM_HANDLER + 0x05) +#define TRC_HVM_IO_READ (TRC_HVM_HANDLER + 0x06) +#define TRC_HVM_IO_WRITE (TRC_HVM_HANDLER + 0x07) +#define TRC_HVM_CR_READ (TRC_HVM_HANDLER + 0x08) +#define TRC_HVM_CR_WRITE (TRC_HVM_HANDLER + 0x09) +#define TRC_HVM_DR_READ (TRC_HVM_HANDLER + 0x0A) +#define TRC_HVM_DR_WRITE (TRC_HVM_HANDLER + 0x0B) +#define TRC_HVM_MSR_READ (TRC_HVM_HANDLER + 0x0C) +#define TRC_HVM_MSR_WRITE (TRC_HVM_HANDLER + 0x0D) +#define TRC_HVM_CPUID (TRC_HVM_HANDLER + 0x0E) +#define TRC_HVM_INTR (TRC_HVM_HANDLER + 0x0F) +#define TRC_HVM_NMI (TRC_HVM_HANDLER + 0x10) +#define TRC_HVM_SMI (TRC_HVM_HANDLER + 0x11) +#define TRC_HVM_VMMCALL (TRC_HVM_HANDLER + 0x12) +#define TRC_HVM_HLT (TRC_HVM_HANDLER + 0x13) +#define TRC_HVM_INVLPG (TRC_HVM_HANDLER + 0x14) /* This structure represents a single trace buffer record. */ struct t_rec { diff -r 2d3ceb082114 -r 58d3f1c6183b xen/include/asm-x86/hvm/trace.h --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/xen/include/asm-x86/hvm/trace.h Mon Feb 26 13:52:25 2007 +0100 @@ -0,0 +1,44 @@ +#ifndef __ASM_X86_HVM_TRACE_H__ +#define __ASM_X86_HVM_TRACE_H__ + +#include + +#define DO_TRC_HVM_VMENTRY 1 +#define DO_TRC_HVM_VMEXIT 1 +#define DO_TRC_HVM_PF_XEN 1 +#define DO_TRC_HVM_PF_INJECT 1 +#define DO_TRC_HVM_INJ_EXC 1 +#define DO_TRC_HVM_INJ_VIRQ 1 +#define DO_TRC_HVM_REINJ_VIRQ 1 +#define DO_TRC_HVM_IO_READ 1 +#define DO_TRC_HVM_IO_WRITE 1 +#define DO_TRC_HVM_CR_READ 1 +#define DO_TRC_HVM_CR_WRITE 1 +#define DO_TRC_HVM_DR_READ 1 +#define DO_TRC_HVM_DR_WRITE 1 +#define DO_TRC_HVM_MSR_READ 1 +#define DO_TRC_HVM_MSR_WRITE 1 +#define DO_TRC_HVM_CPUID 1 +#define DO_TRC_HVM_INTR 1 +#define DO_TRC_HVM_NMI 1 +#define DO_TRC_HVM_SMI 1 +#define DO_TRC_HVM_VMMCALL 1 +#define DO_TRC_HVM_HLT 1 +#define DO_TRC_HVM_INVLPG 1 + +#define HVMTRACE_4D(evt, vcpu, d1, d2, d3, d4) \ + do { \ + if (DO_TRC_HVM_ ## evt) \ + TRACE_5D( \ + TRC_HVM_ ## evt, \ + ((vcpu)->domain->domain_id<<16) + (vcpu)->vcpu_id, \ + d1, d2, d3, d4 \ + ); \ + } while(0) + +#define HVMTRACE_3D(evt, vcpu, d1, d2, d3) HVMTRACE_4D(evt, vcpu, d1, d2, d3, 0) +#define HVMTRACE_2D(evt, vcpu, d1, d2) HVMTRACE_4D(evt, vcpu, d1, d2, 0, 0) +#define HVMTRACE_1D(evt, vcpu, d1) HVMTRACE_4D(evt, vcpu, d1, 0, 0, 0) +#define HVMTRACE_0D(evt, vcpu) HVMTRACE_4D(evt, vcpu, 0, 0, 0, 0) + +#endif //__ASM_X86_HVM_TRACE_H__