Re: [PATCH for-4.5 v6 06/16] xen: Convert vmware_port to xentrace usage

[Don Slutz <dslutz@verizon.com>]

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@verizon.com>
>> ---
>> 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
>