[PATCH 0/2] trace: improve hypercall tracing

[PATCH 0/2] trace: improve hypercall tracing

[David Vrabel]

These patches improve the tracing of hypercalls to make xentrace more
useful for looking at what guests are doing with hypercalls.  Selected
hypercall arguments are included in the trace records and the calls
within a multicall are traced.

These are probably for 4.3.

David

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

[David Vrabel]

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 (the number of calls in
a multicall, and the number of PTE updates in an mmu_update).

To allow tracing tools to distinguish between the two formats, the new
format uses a new event ID (TRC_PV_HYPERCALL_V2).

Signed-off-by: David Vrabel <david.vrabel@citrix.com>
---
 xen/arch/x86/trace.c       |   33 +++++++++++++--------------------
 xen/common/trace.c         |   23 +++++++++++++++++++++++
 xen/include/public/trace.h |    1 +
 xen/include/xen/trace.h    |    2 ++
 4 files changed, 39 insertions(+), 20 deletions(-)

diff --git a/xen/arch/x86/trace.c b/xen/arch/x86/trace.c
index 404f293..2b59017 100644
--- a/xen/arch/x86/trace.c
+++ b/xen/arch/x86/trace.c
@@ -14,35 +14,28 @@
 void trace_hypercall(void)
 {
     struct cpu_user_regs *regs = guest_cpu_user_regs();
+    unsigned long args[5];
 
 #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;
     }
     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->r11;
     }
+
+    __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..47c9a6a 100644
--- a/xen/common/trace.c
+++ b/xen/common/trace.c
@@ -816,6 +816,29 @@ unlock:
         tasklet_schedule(&trace_notify_dom0_tasklet);
 }
 
+void __trace_hypercall(unsigned long op, const unsigned long *args)
+{
+    struct {
+        uint32_t op;
+        uint32_t args[5];
+    } __attribute__((packed)) d;
+    uint32_t *a = d.args;
+
+    d.op = op;
+
+    switch (op) {
+    case __HYPERVISOR_multicall:
+        *a++ = args[1]; /* count */
+        break;
+    case __HYPERVISOR_mmu_update:
+        *a++ = args[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 0dfabe9..38a3f83 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -106,6 +106,7 @@
 #define TRC_PV_GDT_LDT_MAPPING_FAULT (TRC_PV + 10)
 #define TRC_PV_PTWR_EMULATION        (TRC_PV + 11)
 #define TRC_PV_PTWR_EMULATION_PAE    (TRC_PV + 12)
+#define TRC_PV_HYPERCALL_V2          (TRC_PV + 14)
   /* Indicates that addresses in trace record are 64 bits */
 #define TRC_64_FLAG               (0x100) 
 
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 {                                        \
-- 
1.7.2.5

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

[George Dunlap]

On Thu, May 24, 2012 at 11:37 AM, David Vrabel <david.vrabel@citrix.com> 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 (the number of calls in
> a multicall, and the number of PTE updates in an mmu_update).
>
> To allow tracing tools to distinguish between the two formats, the new
> format uses a new event ID (TRC_PV_HYPERCALL_V2).
>
> Signed-off-by: David Vrabel <david.vrabel@citrix.com>

The problem with tracing all the hypercall arguments is that it will
significantly increase the size of traces.  How many arguments to most
hypercalls actually use -- and how many of those are actually just
pointers to guest memory, and useless in a trace record anyway?

 -George

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

[David Vrabel]

On 24/05/12 17:11, George Dunlap wrote:
> On Thu, May 24, 2012 at 11:37 AM, David Vrabel <david.vrabel@citrix.com> 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 (the number of calls in
>> a multicall, and the number of PTE updates in an mmu_update).
>>
>> To allow tracing tools to distinguish between the two formats, the new
>> format uses a new event ID (TRC_PV_HYPERCALL_V2).
>>
>> Signed-off-by: David Vrabel <david.vrabel@citrix.com>
> 
> The problem with tracing all the hypercall arguments is that it will
> significantly increase the size of traces.  How many arguments to most
> hypercalls actually use -- and how many of those are actually just
> pointers to guest memory, and useless in a trace record anyway?

This patch only adds selected arguments to the trace record.

See __trace_hypercall() where we have:

+    switch (op) {
+    case __HYPERVISOR_multicall:
+        *a++ = args[1]; /* count */
+        break;
+    case __HYPERVISOR_mmu_update:
+        *a++ = args[1]; /* count */
+        break;
+    }
+
+    __trace_var(TRC_PV_HYPERCALL_V2, 1,
+                sizeof(uint32_t) * (1 + (a - d.args)), &d);

So, for these calls only one 32-bit argument is added to the trace record.

David

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

[Frediano Ziglio]

On Thu, 2012-05-24 at 11:37 +0100, 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 (the number of calls in
> a multicall, and the number of PTE updates in an mmu_update).
> 

I think that EIP is quite useful as it allow to understand which code in
dom0 call that hypercall.

There is also space for an additional parameter without changing trace
version (adding information in a record should not be a problem).

Frediano

> To allow tracing tools to distinguish between the two formats, the new
> format uses a new event ID (TRC_PV_HYPERCALL_V2).
> 
> Signed-off-by: David Vrabel <david.vrabel@citrix.com>
> ---
>  xen/arch/x86/trace.c       |   33 +++++++++++++--------------------
>  xen/common/trace.c         |   23 +++++++++++++++++++++++
>  xen/include/public/trace.h |    1 +
>  xen/include/xen/trace.h    |    2 ++
>  4 files changed, 39 insertions(+), 20 deletions(-)
> 
> diff --git a/xen/arch/x86/trace.c b/xen/arch/x86/trace.c
> index 404f293..2b59017 100644
> --- a/xen/arch/x86/trace.c
> +++ b/xen/arch/x86/trace.c
> @@ -14,35 +14,28 @@
>  void trace_hypercall(void)
>  {
>      struct cpu_user_regs *regs = guest_cpu_user_regs();
> +    unsigned long args[5];
>  
>  #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;
>      }
>      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->r11;
>      }
> +
> +    __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..47c9a6a 100644
> --- a/xen/common/trace.c
> +++ b/xen/common/trace.c
> @@ -816,6 +816,29 @@ unlock:
>          tasklet_schedule(&trace_notify_dom0_tasklet);
>  }
>  
> +void __trace_hypercall(unsigned long op, const unsigned long *args)
> +{
> +    struct {
> +        uint32_t op;
> +        uint32_t args[5];
> +    } __attribute__((packed)) d;
> +    uint32_t *a = d.args;
> +
> +    d.op = op;
> +
> +    switch (op) {
> +    case __HYPERVISOR_multicall:
> +        *a++ = args[1]; /* count */
> +        break;
> +    case __HYPERVISOR_mmu_update:
> +        *a++ = args[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 0dfabe9..38a3f83 100644
> --- a/xen/include/public/trace.h
> +++ b/xen/include/public/trace.h
> @@ -106,6 +106,7 @@
>  #define TRC_PV_GDT_LDT_MAPPING_FAULT (TRC_PV + 10)
>  #define TRC_PV_PTWR_EMULATION        (TRC_PV + 11)
>  #define TRC_PV_PTWR_EMULATION_PAE    (TRC_PV + 12)
> +#define TRC_PV_HYPERCALL_V2          (TRC_PV + 14)
>    /* Indicates that addresses in trace record are 64 bits */
>  #define TRC_64_FLAG               (0x100) 
>  
> 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 {                                        \

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

[David Vrabel]

On 28/05/12 17:03, Frediano Ziglio wrote:
> On Thu, 2012-05-24 at 11:37 +0100, 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 (the number of calls in
>> a multicall, and the number of PTE updates in an mmu_update).
>>
> 
> I think that EIP is quite useful as it allow to understand which code in
> dom0 call that hypercall.

The EIP was always an address in the hypercall page (i.e.,
hypercall_page + op * sizeof(unsigned long)) and doesn't tell you what
made the hypercall.  You would need one of the addresses off the guest
stack to find the caller.

> There is also space for an additional parameter without changing trace
> version (adding information in a record should not be a problem).

True, but George was keen on keeping the trace record size to a minimum.

I am tempted to use 5 bits of the first extra word to indicate which
parameters are present in the trace record.  This might make the new
format more future-proof, perhaps.

David

[PATCH 2/2] trace: trace hypercalls inside a multicall

[David Vrabel]

From: David Vrabel <david.vrabel@citrix.com>

Add a trace record for every hypercall inside a multicall.

Signed-off-by: David Vrabel <david.vrabel@citrix.com>
---
 xen/common/multicall.c |   29 +++++++++++++++++++++++++++++
 1 files changed, 29 insertions(+), 0 deletions(-)

diff --git a/xen/common/multicall.c b/xen/common/multicall.c
index 6c1a9d7..1da53bb 100644
--- a/xen/common/multicall.c
+++ b/xen/common/multicall.c
@@ -11,6 +11,7 @@
 #include <xen/multicall.h>
 #include <xen/guest_access.h>
 #include <xen/perfc.h>
+#include <xen/trace.h>
 #include <asm/current.h>
 #include <asm/hardirq.h>
 
@@ -19,6 +20,32 @@ typedef long ret_t;
 #define xlat_multicall_entry(mcs)
 #endif
 
+#ifdef COMPAT
+static void __trace_multicall_call(multicall_entry_t *call)
+{
+    unsigned long args[5];
+    int i;
+
+    for (i = 0; i < ARRAY_SIZE(args); i++)
+        args[i] = call->args[i];
+
+    __trace_hypercall(call->op, args);
+}
+#else
+static void __trace_multicall_call(multicall_entry_t *call)
+{
+    __trace_hypercall(call->op, call->args);
+}
+#endif
+
+static void trace_multicall_call(multicall_entry_t *call)
+{
+    if ( !tb_init_done )
+        return;
+
+    __trace_multicall_call(call);
+}
+
 ret_t
 do_multicall(
     XEN_GUEST_HANDLE(multicall_entry_t) call_list, unsigned int nr_calls)
@@ -47,6 +74,8 @@ do_multicall(
             break;
         }
 
+        trace_multicall_call(&mcs->call);
+
         do_multicall_call(&mcs->call);
 
 #ifndef NDEBUG
-- 
1.7.2.5

Re: [PATCH 2/2] trace: trace hypercalls inside a multicall

[Frediano Ziglio]

On Thu, 2012-05-24 at 11:37 +0100, David Vrabel wrote:
> From: David Vrabel <david.vrabel@citrix.com>
> 
> Add a trace record for every hypercall inside a multicall.
> 
> Signed-off-by: David Vrabel <david.vrabel@citrix.com>
> ---
>  xen/common/multicall.c |   29 +++++++++++++++++++++++++++++
>  1 files changed, 29 insertions(+), 0 deletions(-)
> 
> diff --git a/xen/common/multicall.c b/xen/common/multicall.c
> index 6c1a9d7..1da53bb 100644
> --- a/xen/common/multicall.c
> +++ b/xen/common/multicall.c
> @@ -11,6 +11,7 @@
>  #include <xen/multicall.h>
>  #include <xen/guest_access.h>
>  #include <xen/perfc.h>
> +#include <xen/trace.h>
>  #include <asm/current.h>
>  #include <asm/hardirq.h>
>  
> @@ -19,6 +20,32 @@ typedef long ret_t;
>  #define xlat_multicall_entry(mcs)
>  #endif
>  
> +#ifdef COMPAT
> +static void __trace_multicall_call(multicall_entry_t *call)
> +{
> +    unsigned long args[5];
> +    int i;
> +
> +    for (i = 0; i < ARRAY_SIZE(args); i++)
> +        args[i] = call->args[i];
> +
> +    __trace_hypercall(call->op, args);
> +}
> +#else
> +static void __trace_multicall_call(multicall_entry_t *call)
> +{
> +    __trace_hypercall(call->op, call->args);
> +}
> +#endif
> +
> +static void trace_multicall_call(multicall_entry_t *call)
> +{
> +    if ( !tb_init_done )
> +        return;
> +
> +    __trace_multicall_call(call);
> +}
> +
>  ret_t
>  do_multicall(
>      XEN_GUEST_HANDLE(multicall_entry_t) call_list, unsigned int nr_calls)
> @@ -47,6 +74,8 @@ do_multicall(
>              break;
>          }
>  
> +        trace_multicall_call(&mcs->call);
> +
>          do_multicall_call(&mcs->call);
>  
>  #ifndef NDEBUG

Good, I'd personally add a way (subclass perhaps) to exclude such traces
as could be very performance consuming.

I'd also add something like sub op (shadow_op or domctl operations have
sub operations which could be useful to understand).

Frediano

Re: [PATCH 2/2] trace: trace hypercalls inside a multicall

[David Vrabel]

On 28/05/12 17:03, Frediano Ziglio wrote:
> On Thu, 2012-05-24 at 11:37 +0100, David Vrabel wrote:
>> From: David Vrabel <david.vrabel@citrix.com>
>>
>> Add a trace record for every hypercall inside a multicall.
>>
>> Signed-off-by: David Vrabel <david.vrabel@citrix.com>
>> ---
[...]
> Good, I'd personally add a way (subclass perhaps) to exclude such traces
> as could be very performance consuming.

Yes, that sounds like a good idea.

> I'd also add something like sub op (shadow_op or domctl operations have
> sub operations which could be useful to understand).

Patches welcome! ;)

David