[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: [Xen-devel] [PATCH for-4.5 v6 06/16] xen: Convert vmware_port to xentrace usage
- To: George Dunlap <george.dunlap@xxxxxxxxxxxxx>, Don Slutz <dslutz@xxxxxxxxxxx>, xen-devel@xxxxxxxxxxxxx
- From: Don Slutz <dslutz@xxxxxxxxxxx>
- Date: Wed, 24 Sep 2014 15:07:38 -0400
- Cc: Kevin Tian <kevin.tian@xxxxxxxxx>, Keir Fraser <keir@xxxxxxx>, Ian Campbell <ian.campbell@xxxxxxxxxx>, Stefano Stabellini <stefano.stabellini@xxxxxxxxxxxxx>, Jun Nakajima <jun.nakajima@xxxxxxxxx>, Eddie Dong <eddie.dong@xxxxxxxxx>, Ian Jackson <ian.jackson@xxxxxxxxxxxxx>, Tim Deegan <tim@xxxxxxx>, Aravind Gopalakrishnan <Aravind.Gopalakrishnan@xxxxxxx>, Jan Beulich <jbeulich@xxxxxxxx>, Andrew Cooper <andrew.cooper3@xxxxxxxxxx>, Boris Ostrovsky <boris.ostrovsky@xxxxxxxxxx>, Suravee Suthikulpanit <suravee.suthikulpanit@xxxxxxx>
- Delivery-date: Wed, 24 Sep 2014 19:07:53 +0000
- List-id: Xen developer discussion <xen-devel.lists.xen.org>
On 09/24/14 13:27, George Dunlap wrote:
On 09/20/2014 07:07 PM, Don Slutz wrote:
Reduce the VMPORT_DBG_LOG calls.
You should also have mentioned that you added hew HVMTRACE macros
which will log the TSC value.
The reason the HVMTRACE macros don't log the TSC values is that for
the most part you can get all the timing information you need from the
TSC on the vmexit and vmenter. Looking at where you've added the TSC
values, I don't really see how it adds anything except bloat to the
log. Is there a reason you need to know exactly when these different
things happened, instead of just being able to bracket them between
VMENTER and VMEXITs?
I did want a way to know how long the VMware code was taking. I am
not sure this is required.
For example:
CPU1 2899550319282 (+ 4170) VMEXIT [ exitcode = 0x00000000,
rIP = 0x00007fad13ffec8c ]
CPU1 2899550320086 (+ 804) TRAP_GP [ inst_len = 1 edx =
0x00005658 exitinfo1 = 0x0000000000000000 exitinfo2 = 0x0000000000000000 ]
CPU1 2899550325054 (+ 4968) VMPORT_READ_BEFORE [ eax = 0x564d5868
ebx = 0x000001b3 ecx = 0x0003001e edx = 0x00005658 esi = 0x00000000 edi
= 0x000001b3 ]
CPU1 2899550326050 (+ 996) VMPORT_READ_AFTER [ eax = 0x564d5868
ebx = 0x000001b3 ecx = 0x0001001e edx = 0x00005658 esi = 0x00000000 edi
= 0x000001b3 ]
CPU1 2899550326722 (+ 672) vlapic_accept_pic_intr [ i8259_target =
1, accept_pic_int = 0 ]
CPU1 2899550327454 (+ 732) VMENTRY
But I am happy to drop the new log TSC macros.
Signed-off-by: Don Slutz <dslutz@xxxxxxxxxxx>
---
v6:
Dropped the attempt to use svm_nextrip_insn_length via
__get_instruction_length (added in v2). Just always look
at upto 15 bytes on AMD.
v5:
exitinfo1 is used twice.
Fixed.
xen/arch/x86/hvm/svm/svm.c | 20 ++++++++++++++---
xen/arch/x86/hvm/vmware/vmport.c | 48
++++++++++++++++++++++------------------
xen/arch/x86/hvm/vmx/vmx.c | 12 ++++++++++
xen/include/asm-x86/hvm/trace.h | 45
+++++++++++++++++++++++++++++++++++++
xen/include/asm-x86/hvm/vmport.h | 6 -----
xen/include/public/trace.h | 12 ++++++++++
6 files changed, 113 insertions(+), 30 deletions(-)
diff --git a/xen/arch/x86/hvm/svm/svm.c b/xen/arch/x86/hvm/svm/svm.c
index ea99dfb..716dda1 100644
--- a/xen/arch/x86/hvm/svm/svm.c
+++ b/xen/arch/x86/hvm/svm/svm.c
@@ -2081,10 +2081,18 @@ static void svm_vmexit_gp_intercept(struct
cpu_user_regs *regs,
*/
unsigned long inst_len = 15;
unsigned long inst_addr = svm_rip2pointer(v);
- int rc;
+ uint32_t starting_rdx = regs->rdx;
+ int rc = vmport_gp_check(regs, v, &inst_len, inst_addr,
+ vmcb->exitinfo1, vmcb->exitinfo2);
+
+ if ( hvm_long_mode_enabled(v) )
+ HVMTRACE_LONG2_C4D(TRAP_GP, inst_len, starting_rdx,
+ TRC_PAR_LONG(vmcb->exitinfo1),
+ TRC_PAR_LONG(vmcb->exitinfo2));
+ else
+ HVMTRACE_C4D(TRAP_GP, inst_len, starting_rdx, vmcb->exitinfo1,
+ vmcb->exitinfo2);
- rc = vmport_gp_check(regs, v, &inst_len, inst_addr,
- vmcb->exitinfo1, vmcb->exitinfo2);
if ( !rc )
__update_guest_eip(regs, inst_len);
else
@@ -2097,6 +2105,12 @@ static void svm_vmexit_gp_intercept(struct
cpu_user_regs *regs,
(unsigned long)vmcb->exitinfo2,
regs->error_code,
regs->rip, inst_addr, inst_len, regs->rax,
regs->rbx,
regs->rcx, regs->rdx, regs->rsi, regs->rdi);
+ if ( hvm_long_mode_enabled(v) )
+ HVMTRACE_LONG_C5D(TRAP_GP_UNKNOWN, rc, regs->rax,
regs->rbx, regs->rcx,
+ TRC_PAR_LONG(inst_addr));
+ else
+ HVMTRACE_C5D(TRAP_GP_UNKNOWN, rc, regs->rax, regs->rbx,
regs->rcx,
+ inst_addr);
hvm_inject_hw_exception(TRAP_gp_fault, vmcb->exitinfo1);
}
}
diff --git a/xen/arch/x86/hvm/vmware/vmport.c
b/xen/arch/x86/hvm/vmware/vmport.c
index 811c303..962ee32 100644
--- a/xen/arch/x86/hvm/vmware/vmport.c
+++ b/xen/arch/x86/hvm/vmware/vmport.c
@@ -18,6 +18,7 @@
#include <asm/hvm/hvm.h>
#include <asm/hvm/support.h>
#include <asm/hvm/vmport.h>
+#include <asm/hvm/trace.h>
#include "backdoor_def.h"
#include "guest_msg_def.h"
@@ -66,12 +67,15 @@ int vmport_ioport(int dir, uint32_t port,
uint32_t bytes, uint32_t *val)
uint64_t saved_rax = regs->rax;
uint64_t value;
- VMPORT_DBG_LOG(VMPORT_LOG_TRACE,
- "VMware trace dir=%d bytes=%u ip=%"PRIx64"
cmd=%d ax=%"
- PRIx64" bx=%"PRIx64" cx=%"PRIx64"
dx=%"PRIx64" si=%"
- PRIx64" di=%"PRIx64"\n", dir, bytes,
- regs->rip, cmd, regs->rax, regs->rbx, regs->rcx,
- regs->rdx, regs->rsi, regs->rdi);
+ if ( dir == IOREQ_READ )
+ HVMTRACE_ND(VMPORT_READ_BEFORE, 0, 1/*cycles*/, 6,
+ regs->rax, regs->rbx, regs->rcx,
+ regs->rdx, regs->rsi, regs->rdi);
+ else
+ HVMTRACE_ND(VMPORT_WRITE_AFTER_BEFORE, 0, 1/*cycles*/, 6,
+ regs->rax, regs->rbx, regs->rcx,
+ regs->rdx, regs->rsi, regs->rdi);
Adding trace points in a separate patch is one thing, but adding code
like this and then removing it in a later patch is really poor form;
it could potentially make bisection difficult too, if (for example)
the output is so verbose in that short window as to make it unusable
between those changesets.
I think you should go back to the previous patches and remove all the
VMPORT_DBG_LOG()s that don't survive until the end of the series.
Unless, that is, you think that you might be making the case to accept
patches 1-5 for 4.5 without this patch; in which case it may make
sense to leave it the way it is.
That was a big part of it. I can go and remove the excess. At this
time I am expecting that 1-7 will make 4.5
We normally don't log both BEFORE and AFTER states of things like
hypercalls -- just logging the outcome of what the hypervisor did
should be sufficient, shouldn't it?
Not that clear with this poorly build hyper-call.
Do you really need to know the value of things that got clobbered?
When checking on the complex state machine that is the "RPC" code
it was very helpful. With that code moving to QEMU, the before and
after is not so important.
Here is a real example:
CPU2 865821836508576 (+ 2562) VMEXIT [ exitcode = 0x00000000,
rIP = 0x00007f68a8b17c8c ]
CPU2 865821836509362 (+ 786) TRAP_GP [ inst_len = 1 edx =
0x00025658 exitinfo1 = 0x0000000000000000 exitinfo2 = 0x0000000000000000 ]
CPU2 865821836514132 (+ 4770) VMPORT_READ_BEFORE [ eax =
0x564d5868 ebx = 0x00000034 ecx = 0x0002001e edx = 0x00025658 esi =
0x00000000 edi = 0x000001be ]
CPU2 865821836597832 (+ 83700) VMPORT_READ_AFTER [ eax = 0x564d5868
ebx = 0x00000034 ecx = 0x0001001e edx = 0x00025658 esi = 0x00000000 edi
= 0x000001be ]
CPU2 865821836598756 (+ 924) vlapic_accept_pic_intr [ i8259_target
= 1, accept_pic_int = 0 ]
CPU2 865821836605602 (+ 6846) vlapic_accept_pic_intr [ i8259_target
= 1, accept_pic_int = 0 ]
CPU2 865821836606436 (+ 834) VMENTRY
CPU2 865821836609712 (+ 3276) VMEXIT [ exitcode = 0x00000000,
rIP = 0x00007f68a8b17c8c ]
CPU2 865821836610654 (+ 942) TRAP_GP [ inst_len = 1 edx =
0x00025658 exitinfo1 = 0x0000000000000000 exitinfo2 = 0x0000000000000000 ]
CPU2 865821836616828 (+ 6174) VMPORT_READ_BEFORE [ eax =
0x564d5868 ebx = 0x00000034 ecx = 0x0003001e edx = 0x00025658 esi =
0x00000000 edi = 0x000001be ]
CPU2 865821836617800 (+ 972) VMPORT_READ_AFTER [ eax = 0x564d5868
ebx = 0x00000011 ecx = 0x0003001e edx = 0x00015658 esi = 0x00000000 edi
= 0x000001be ]
CPU2 865821836618664 (+ 864) vlapic_accept_pic_intr [ i8259_target
= 1, accept_pic_int = 0 ]
CPU2 865821836619444 (+ 780) VMENTRY
Note that in the one "RPC" call,
grep VMPORT_READ_BEFORE ~/zz-xentrace-vmware3-0.out | wc
1592 39800 256312
It took 1592 #GP traps to handle it, and 9643628760 tsc cycles.
You've got tracing in the error paths for when things don't go as you
expected.
Also, same comment with the cycles: I don't see any value in logging
how long it took to get from the VMEXIT to here or from here to
anywhere else; it just makes the log really bloated.
Since you feel so strongly about this, I can drop it.
+
switch ( cmd )
{
case BDOOR_CMD_GETMHZ:
@@ -143,19 +147,17 @@ int vmport_ioport(int dir, uint32_t port,
uint32_t bytes, uint32_t *val)
regs->rax = 0x0;
break;
default:
- VMPORT_DBG_LOG(VMPORT_LOG_ERROR,
- "VMware bytes=%d dir=%d cmd=%d",
- bytes, dir, cmd);
+ HVMTRACE_ND(VMPORT_UNKNOWN, 0, 1/*cycles*/, 6,
+ (bytes << 8) + dir, cmd, regs->rbx,
+ regs->rcx, regs->rsi, regs->rdi);
You do realize the maximum number of bytes you can log is 7, not 6,
right? The macro stops at 6, but that's just where Keir got tired, I
think; if you want ot log more registers here you can extend it to 7.
Nope, that I did not know. However the 1 additional 32bit value may
not be that helpful.
Also, I think for clarity you should (bytes << 8) | dir rather than +dir.
Sure, will change.
break;
}
- VMPORT_DBG_LOG(VMPORT_LOG_VMWARE_AFTER,
- "VMware after ip=%"PRIx64" cmd=%d
ax=%"PRIx64" bx=%"
- PRIx64" cx=%"PRIx64" dx=%"PRIx64"
si=%"PRIx64" di=%"
- PRIx64"\n",
- regs->rip, cmd, regs->rax, regs->rbx, regs->rcx,
- regs->rdx, regs->rsi, regs->rdi);
+
if ( dir == IOREQ_READ )
{
+ HVMTRACE_ND(VMPORT_READ_AFTER, 0, 1/*cycles*/, 6,
+ regs->rax, regs->rbx, regs->rcx,
+ regs->rdx, regs->rsi, regs->rdi);
switch ( bytes )
{
case 1:
@@ -171,17 +173,21 @@ int vmport_ioport(int dir, uint32_t port,
uint32_t bytes, uint32_t *val)
*val = regs->rax;
}
else
+ {
+ HVMTRACE_ND(VMPORT_WRITE_AFTER, 0, 1/*cycles*/, 6,
+ regs->rax, regs->rbx, regs->rcx,
+ regs->rdx, regs->rsi, regs->rdi);
regs->rax = saved_rax;
+ }
}
else
{
+ if ( hvm_long_mode_enabled(current) )
+ HVMTRACE_LONG_C4D(VMPORT_BAD, dir, bytes, regs->rax,
+ TRC_PAR_LONG(regs->rip));
+ else
+ HVMTRACE_C4D(VMPORT_BAD, dir, bytes, regs->rax, regs->rip);
rc = X86EMUL_UNHANDLEABLE;
- VMPORT_DBG_LOG(VMPORT_LOG_ERROR,
- "Not VMware %x vs %x; ip=%"PRIx64" ax=%"PRIx64
- " bx=%"PRIx64" cx=%"PRIx64" dx=%"PRIx64"
si=%"PRIx64
- " di=%"PRIx64"",
- magic, BDOOR_MAGIC, regs->rip, regs->rax,
regs->rbx,
- regs->rcx, regs->rdx, regs->rsi, regs->rdi);
}
return rc;
diff --git a/xen/arch/x86/hvm/vmx/vmx.c b/xen/arch/x86/hvm/vmx/vmx.c
index 73f55f2..5395028 100644
--- a/xen/arch/x86/hvm/vmx/vmx.c
+++ b/xen/arch/x86/hvm/vmx/vmx.c
@@ -2613,6 +2613,12 @@ static void vmx_vmexit_gp_intercept(struct
cpu_user_regs *regs,
__vmread(VM_EXIT_INSTRUCTION_LEN, &inst_len);
__vmread(VM_EXIT_INTR_ERROR_CODE, &ecode);
+ if ( hvm_long_mode_enabled(v) )
+ HVMTRACE_LONG2_C4D(TRAP_GP, inst_len, regs->rdx,
TRC_PAR_LONG(ecode),
+ TRC_PAR_LONG(exit_qualification));
+ else
+ HVMTRACE_C4D(TRAP_GP, inst_len, regs->rdx, ecode,
exit_qualification);
Do you think anyone will need this 2 years from now? That is, will
this actually be useful in understanding guest behavior, or is this
mostly to help you debug the hypervisor as you're developing it?
I can see a need for it. I would hope that Intel (and AMD) would not
change the hardware so this info is needed, but I have seen this
happen in the past.
I would have no issue with making some of these compile time
conditional (like only in debug=y builds).
I'd like to say more about my general theory for traces, but my brain
has about shut down... I'll send this so you can have the comments
I've got so far, and I'll come back to it tomorrow.
Just one more thing...
+
#ifndef NDEBUG
orig_inst_len = inst_len;
#endif
@@ -2636,6 +2642,12 @@ static void vmx_vmexit_gp_intercept(struct
cpu_user_regs *regs,
regs->rip, inst_addr, orig_inst_len, inst_len,
regs->rax, regs->rbx, regs->rcx, regs->rdx,
regs->rsi,
regs->rdi);
+ if ( hvm_long_mode_enabled(v) )
+ HVMTRACE_LONG_C5D(TRAP_GP_UNKNOWN, rc, regs->rax,
regs->rbx, regs->rcx,
+ TRC_PAR_LONG(inst_addr));
+ else
+ HVMTRACE_C5D(TRAP_GP_UNKNOWN, rc, regs->rax, regs->rbx,
regs->rcx,
+ inst_addr);
hvm_inject_hw_exception(TRAP_gp_fault, ecode);
}
}
diff --git a/xen/include/asm-x86/hvm/trace.h
b/xen/include/asm-x86/hvm/trace.h
index de802a6..8af2d6a 100644
--- a/xen/include/asm-x86/hvm/trace.h
+++ b/xen/include/asm-x86/hvm/trace.h
@@ -52,8 +52,20 @@
#define DO_TRC_HVM_LMSW64 DEFAULT_HVM_MISC
#define DO_TRC_HVM_REALMODE_EMULATE DEFAULT_HVM_MISC
#define DO_TRC_HVM_TRAP DEFAULT_HVM_MISC
+#define DO_TRC_HVM_TRAP64 DEFAULT_HVM_MISC
#define DO_TRC_HVM_TRAP_DEBUG DEFAULT_HVM_MISC
#define DO_TRC_HVM_VLAPIC DEFAULT_HVM_MISC
+#define DO_TRC_HVM_TRAP_GP DEFAULT_HVM_MISC
+#define DO_TRC_HVM_TRAP_GP64 DEFAULT_HVM_MISC
+#define DO_TRC_HVM_TRAP_GP_UNKNOWN DEFAULT_HVM_MISC
+#define DO_TRC_HVM_TRAP_GP_UNKNOWN64 DEFAULT_HVM_MISC
+#define DO_TRC_HVM_VMPORT_READ_BEFORE DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_WRITE_AFTER_BEFORE DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_READ_AFTER DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_WRITE_AFTER DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_BAD DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_BAD64 DEFAULT_HVM_IO
+#define DO_TRC_HVM_VMPORT_UNKNOWN DEFAULT_HVM_IO
#define TRC_PAR_LONG(par) ((par)&0xFFFFFFFF),((par)>>32)
@@ -98,6 +110,21 @@
#define HVMTRACE_0D(evt) \
HVMTRACE_ND(evt, 0, 0, 0, 0, 0, 0, 0, 0, 0)
+#define HVMTRACE_C6D(evt, d1, d2, d3, d4, d5, d6) \
+ HVMTRACE_ND(evt, 0, 1, 6, d1, d2, d3, d4, d5, d6)
+#define HVMTRACE_C5D(evt, d1, d2, d3, d4, d5) \
+ HVMTRACE_ND(evt, 0, 1, 5, d1, d2, d3, d4, d5, 0)
+#define HVMTRACE_C4D(evt, d1, d2, d3, d4) \
+ HVMTRACE_ND(evt, 0, 1, 4, d1, d2, d3, d4, 0, 0)
+#define HVMTRACE_C3D(evt, d1, d2, d3) \
+ HVMTRACE_ND(evt, 0, 1, 3, d1, d2, d3, 0, 0, 0)
+#define HVMTRACE_C2D(evt, d1, d2) \
+ HVMTRACE_ND(evt, 0, 1, 2, d1, d2, 0, 0, 0, 0)
+#define HVMTRACE_C1D(evt, d1) \
+ HVMTRACE_ND(evt, 0, 1, 1, d1, 0, 0, 0, 0, 0)
+#define HVMTRACE_C0D(evt) \
+ HVMTRACE_ND(evt, 0, 1, 0, 0, 0, 0, 0, 0, 0)
+
#define HVMTRACE_LONG_1D(evt, d1) \
HVMTRACE_2D(evt ## 64, (d1) & 0xFFFFFFFF, (d1)
>> 32)
#define HVMTRACE_LONG_2D(evt, d1, d2, ...) \
@@ -107,6 +134,24 @@
#define HVMTRACE_LONG_4D(evt, d1, d2, d3, d4, ...) \
HVMTRACE_5D(evt ## 64, d1, d2, d3, d4)
+#define HVMTRACE_LONG_C1D(evt, d1) \
+ HVMTRACE_C2D(evt ## 64, (d1) & 0xFFFFFFFF, (d1)
>> 32)
+#define HVMTRACE_LONG_C2D(evt, d1, d2, ...) \
+ HVMTRACE_C3D(evt ## 64, d1, d2)
+#define HVMTRACE_LONG_C3D(evt, d1, d2, d3, ...) \
+ HVMTRACE_C4D(evt ## 64, d1, d2, d3)
+#define HVMTRACE_LONG_C4D(evt, d1, d2, d3, d4, ...) \
+ HVMTRACE_C5D(evt ## 64, d1, d2, d3, d4)
+#define HVMTRACE_LONG_C5D(evt, d1, d2, d3, d4, d5, ...) \
+ HVMTRACE_C6D(evt ## 64, d1, d2, d3, d4, d5)
+
+#define HVMTRACE_LONG2_C2D(evt, d1, d2, ...) \
+ HVMTRACE_C4D(evt ## 64, d1, d2)
+#define HVMTRACE_LONG2_C3D(evt, d1, d2, d3, ...) \
+ HVMTRACE_C5D(evt ## 64, d1, d2, d3)
+#define HVMTRACE_LONG2_C4D(evt, d1, d2, d3, d4, ...) \
+ HVMTRACE_C6D(evt ## 64, d1, d2, d3, d4)
+
#endif /* __ASM_X86_HVM_TRACE_H__ */
/*
diff --git a/xen/include/asm-x86/hvm/vmport.h
b/xen/include/asm-x86/hvm/vmport.h
index c4f3926..401cbf4 100644
--- a/xen/include/asm-x86/hvm/vmport.h
+++ b/xen/include/asm-x86/hvm/vmport.h
@@ -25,12 +25,6 @@
#define VMPORT_LOG_VGP_UNKNOWN (1 << 3)
#define VMPORT_LOG_REALMODE_GP (1 << 4)
-#define VMPORT_LOG_GP_NOT_VMWARE (1 << 9)
-
-#define VMPORT_LOG_TRACE (1 << 16)
-#define VMPORT_LOG_ERROR (1 << 17)
-#define VMPORT_LOG_VMWARE_AFTER (1 << 18)
-
If you remove the debug statements in earlier patches, remember to
remove these as well.
Sure.
-Don Slutz
-George
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel
|
