Re: [PATCH 2/3] trace: improve usefulness of hypercall trace record

[George Dunlap <george.dunlap@eu.citrix.com>]

On 31/05/12 12:06, David Vrabel wrote:
> From: David Vrabel<david.vrabel@citrix.com>
>
> Trace hypercalls using a more useful trace record format.
>
> The EIP field is removed (it was always somewhere in the hypercall
> page) and include selected hypercall arguments (e.g., the number of
> calls in a multicall, and the number of PTE updates in an mmu_update
> etc.).  12 bits in the first extra word are used to indicate which
> arguments are present in the record and what size they are (32 or
> 64-bit).
>
> This is an incompatible record format so a new event ID is used so
> tools can distinguish between the two formats.
>
> Signed-off-by: David Vrabel<david.vrabel@citrix.com>
[post-4.2]
Acked-by: George Dunlap <george.dunlap@eu.citrix.com>
> ---
>   tools/xentrace/formats         |    1 +
>   tools/xentrace/xentrace_format |    6 +++++
>   xen/arch/x86/trace.c           |   35 +++++++++++++-----------------
>   xen/common/trace.c             |   45 ++++++++++++++++++++++++++++++++++++++++
>   xen/include/public/trace.h     |   30 ++++++++++++++++++++++++++
>   xen/include/xen/trace.h        |    2 +
>   6 files changed, 99 insertions(+), 20 deletions(-)
>
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index 71220c0..fa935c8 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -104,6 +104,7 @@
>   0x0020110b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  ptwr_emulation      [ addr = 0x%(4)08x%(3)08x, rip = 0x%(6)08x%(5)08x, npte = 0x%(2)08x%(1)08x ]
>   0x0020100c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  ptwr_emulation_pae  [ addr = 0x%(3)08x, eip = 0x%(4)08x, npte = 0x%(2)08x%(1)08x ]
>   0x0020110c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  ptwr_emulation_pae  [ addr = 0x%(4)08x%(3)08x, rip = 0x%(6)08x%(5)08x, npte = 0x%(2)08x%(1)08x ]
> +0x0020100d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hypercall  [ op = 0x%(1)08x ]
>
>   0x0040f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  shadow_not_shadow                 [ gl1e = 0x%(2)08x%(1)08x, va = 0x%(3)08x, flags = 0x%(4)08x ]
>   0x0040f101  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  shadow_not_shadow                 [ gl1e = 0x%(2)08x%(1)08x, va = 0x%(4)08x%(3)08x, flags = 0x%(5)08x ]
> diff --git a/tools/xentrace/xentrace_format b/tools/xentrace/xentrace_format
> index e13b05b..6dab034 100644
> --- a/tools/xentrace/xentrace_format
> +++ b/tools/xentrace/xentrace_format
> @@ -111,6 +111,8 @@ D7REC  = "IIIIIII"
>   last_tsc = [0]
>
>   TRC_TRACE_IRQ = 0x1f004
> +TRC_PV_HYPERCALL_V2 = 0x20100d
> +
>   NR_VECTORS = 256
>   irq_measure = [{'count':0, 'tot_cycles':0, 'max_cycles':0}] * NR_VECTORS
>
> @@ -197,6 +199,10 @@ while not interrupted:
>               d3 = irq_measure[d1]['tot_cycles']
>               d4 = irq_measure[d1]['max_cycles']
>
> +        if event == TRC_PV_HYPERCALL_V2:
> +            # Mask off the argument present bits.
> +            args[1]&= 0x000fffff
> +
>           #tsc = (tscH<<32) | tscL
>
>           #print i, tsc
> diff --git a/xen/arch/x86/trace.c b/xen/arch/x86/trace.c
> index 404f293..30269e9 100644
> --- a/xen/arch/x86/trace.c
> +++ b/xen/arch/x86/trace.c
> @@ -14,35 +14,30 @@
>   void trace_hypercall(void)
>   {
>       struct cpu_user_regs *regs = guest_cpu_user_regs();
> +    unsigned long args[6];
>
>   #ifdef __x86_64__
>       if ( is_pv_32on64_vcpu(current) )
>       {
> -        struct {
> -            u32 eip,eax;
> -        } __attribute__((packed)) d;
> -
> -        d.eip = regs->eip;
> -        d.eax = regs->eax;
> -
> -        __trace_var(TRC_PV_HYPERCALL, 1, sizeof(d),&d);
> +        args[0] = regs->ebx;
> +        args[1] = regs->ecx;
> +        args[2] = regs->edx;
> +        args[3] = regs->esi;
> +        args[4] = regs->edi;
> +        args[5] = regs->ebp;
>       }
>       else
>   #endif
>       {
> -        struct {
> -            unsigned long eip;
> -            u32 eax;
> -        } __attribute__((packed)) d;
> -        u32 event;
> -
> -        event = TRC_PV_HYPERCALL;
> -        event |= TRC_64_FLAG;
> -        d.eip = regs->eip;
> -        d.eax = regs->eax;
> -
> -        __trace_var(event, 1/*tsc*/, sizeof(d),&d);
> +        args[0] = regs->rdi;
> +        args[1] = regs->rsi;
> +        args[2] = regs->rdx;
> +        args[3] = regs->r10;
> +        args[4] = regs->r8;
> +        args[5] = regs->r9;
>       }
> +
> +    __trace_hypercall(regs->eax, args);
>   }
>
>   void __trace_pv_trap(int trapnr, unsigned long eip,
> diff --git a/xen/common/trace.c b/xen/common/trace.c
> index cacaeb2..833f6b9 100644
> --- a/xen/common/trace.c
> +++ b/xen/common/trace.c
> @@ -816,6 +816,51 @@ unlock:
>           tasklet_schedule(&trace_notify_dom0_tasklet);
>   }
>
> +void __trace_hypercall(unsigned long op, const unsigned long *args)
> +{
> +    struct {
> +        uint32_t op;
> +        uint32_t args[6];
> +    } __attribute__((packed)) d;
> +    uint32_t *a = d.args;
> +
> +#define APPEND_ARG32(i)                         \
> +    do {                                        \
> +        unsigned i_ = (i);                      \
> +        *a++ = args[(i_)];                      \
> +        d.op |= TRC_PV_HYPERCALL_V2_ARG_32(i_); \
> +    } while( 0 )
> +
> +    /*
> +     * This shouldn't happen as @op should be small enough but just in
> +     * case, warn if the argument bits in the trace record would
> +     * clobber the hypercall op.
> +     */
> +    WARN_ON(op&  TRC_PV_HYPERCALL_V2_ARG_MASK);
> +
> +    d.op = op;
> +
> +    switch ( op )
> +    {
> +    case __HYPERVISOR_mmu_update:
> +        APPEND_ARG32(1); /* count */
> +        break;
> +    case __HYPERVISOR_multicall:
> +        APPEND_ARG32(1); /* count */
> +        break;
> +    case __HYPERVISOR_grant_table_op:
> +        APPEND_ARG32(0); /* cmd */
> +        APPEND_ARG32(2); /* count */
> +        break;
> +    case __HYPERVISOR_mmuext_op:
> +        APPEND_ARG32(1); /* count */
> +        break;
> +    }
> +
> +    __trace_var(TRC_PV_HYPERCALL_V2, 1,
> +                sizeof(uint32_t) * (1 + (a - d.args)),&d);
> +}
> +
>   /*
>    * Local variables:
>    * mode: C
> diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
> index 1f154bb..ef43b23 100644
> --- a/xen/include/public/trace.h
> +++ b/xen/include/public/trace.h
> @@ -107,6 +107,36 @@
>   #define TRC_PV_GDT_LDT_MAPPING_FAULT (TRC_PV_ENTRY + 10)
>   #define TRC_PV_PTWR_EMULATION        (TRC_PV_ENTRY + 11)
>   #define TRC_PV_PTWR_EMULATION_PAE    (TRC_PV_ENTRY + 12)
> +#define TRC_PV_HYPERCALL_V2          (TRC_PV_ENTRY + 13)
> +
> +/*
> + * TRC_PV_HYPERCALL_V2 format
> + *
> + * Only some of the hypercall argument are recorded. Bit fields A0 to
> + * A5 in the first extra word are set if the argument is present and
> + * the arguments themselves are packed sequentially in the following
> + * words.
> + *
> + * The TRC_64_FLAG bit is not set for these events (even if there are
> + * 64-bit arguments in the record).
> + *
> + * Word
> + * 0    bit 31 30|29 28|27 26|25 24|23 22|21 20|19 ... 0
> + *          A5   |A4   |A3   |A2   |A1   |A0   |Hypercall op
> + * 1    First 32 bit (or low word of first 64 bit) arg in record
> + * 2    Second 32 bit (or high word of first 64 bit) arg in record
> + * ...
> + *
> + * A0-A5 bitfield values:
> + *
> + *   00b  Argument not present
> + *   01b  32-bit argument present
> + *   10b  64-bit argument present
> + *   11b  Reserved
> + */
> +#define TRC_PV_HYPERCALL_V2_ARG_32(i) (0x1<<  (20 + 2*(i)))
> +#define TRC_PV_HYPERCALL_V2_ARG_64(i) (0x2<<  (20 + 2*(i)))
> +#define TRC_PV_HYPERCALL_V2_ARG_MASK  (0xfff00000)
>
>   #define TRC_SHADOW_NOT_SHADOW                 (TRC_SHADOW +  1)
>   #define TRC_SHADOW_FAST_PROPAGATE             (TRC_SHADOW +  2)
> diff --git a/xen/include/xen/trace.h b/xen/include/xen/trace.h
> index b32f6c5..f601aeb 100644
> --- a/xen/include/xen/trace.h
> +++ b/xen/include/xen/trace.h
> @@ -44,6 +44,8 @@ static inline void trace_var(u32 event, int cycles, int extra,
>           __trace_var(event, cycles, extra, extra_data);
>   }
>
> +void __trace_hypercall(unsigned long call, const unsigned long *args);
> +
>   /* Convenience macros for calling the trace function. */
>   #define TRACE_0D(_e)                            \
>       do {                                        \