xentrace: fix tracing for 64bit guests

Xen tracing some times ago used to put values of type 'long' into the
trace buffer. This has changed to uint32_t. Some trace points log
virtual addresses, which get cropped to 32bit in this case. There were
some inline functions to handle at least PF_XEN and VMEXIT, which
caused a lot of code duplication. The attached patch fixes several
issues:
1. fix and extend tools/xentrace/formats
2. Fix xentrace_format to handle up to 7 parameters
3. create convenience macros to properly log long values
4. remove the inline functions in hvm/trace.h and replace them by macros
5. Change the CPUID trace to work correctly
6. group HVM trace points enable mechanism

I used a similar approach as in PV tracing with bit 8 indicating 64bit
pointers.

Signed-off-by: Andre Przywara <andre.przywara@amd.com>

2 files changed, 58 insertions, 23 deletions

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 3028ec0b0f..0a63702463 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -1,48 +1,67 @@
 0x00000000  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  unknown (0x%(event)016x)  [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x ]
 
-0x0001f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  lost_records        0x%(1)08x
-0x0001f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  wrap_buffer         0x%(1)08x
-0x0001f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_change          0x%(1)08x
+0x0001f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  lost_records      0x%(1)08x
+0x0001f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  wrap_buffer       0x%(1)08x
+0x0001f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  cpu_change        0x%(1)08x
 
-0x0002f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain	[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain	[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep		[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake		[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield		[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block		[ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x0002f007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown		[ domid = 0x%(1)08x, edomid = 0x%(2)08x, reason = 0x%(3)08x ]
+0x0002f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep      [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake       [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
+0x0002f007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown	  [ domid = 0x%(1)08x, edomid = 0x%(2)08x, reason = 0x%(3)08x ]
 0x0002f008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_ctl
-0x0002f009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_adjdom		[ domid = 0x%(1)08x ]
-0x0002f00a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler	[ prev<domid:edomid> = 0x%(1)08x : 0x%(2)08x, next<domid:edomid> = 0x%(3)08x : 0x%(4)08x ]
+0x0002f009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_adjdom      [ domid = 0x%(1)08x ]
+0x0002f00a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler [ prev<domid:edomid> = 0x%(1)08x : 0x%(2)08x, next<domid:edomid> = 0x%(3)08x : 0x%(4)08x ]
 0x0002f00B  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  s_timer_fn
 0x0002f00c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  t_timer_fn
 0x0002f00d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  dom_timer_fn
+0x0002f00e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infprev    [ old_domid = 0x%(1)08x, runtime = %(2)d ]
+0x0002f00f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ new_domid = 0x%(1)08x, time = %(2)d, r_time = %(3)d ]
 
 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, exitcode = 0x%(2)08x, rIP  = 0x%(3)08x ]
-0x00082001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_XEN      [ dom:vcpu = 0x%(1)08x, errorcode = 0x%(2)02x, virt = 0x%(3)08x ]
-0x00082002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_INJECT   [ dom:vcpu = 0x%(1)08x, virt = 0x%(2)08x, errorcode = 0x%(3)02x ]
+0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ dom:vcpu = 0x%(1)08x, exitcode = 0x%(2)08x, rIP  = 0x%(3)016x ]
+0x00082001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_XEN      [ dom:vcpu = 0x%(1)08x, errorcode = 0x%(3)02x, virt = 0x%(2)08x ]
+0x00082101  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_XEN      [ dom:vcpu = 0x%(1)08x, errorcode = 0x%(3)02x, virt = 0x%(2)016x ]
+0x00082002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_INJECT   [ dom:vcpu = 0x%(1)08x, errorcode = 0x%(2)02x, virt = 0x%(3)08x ]
+0x00082102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_INJECT   [ dom:vcpu = 0x%(1)08x,  errorcode = 0x%(2)02x, virt = 0x%(3)016x ]
 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 ]
+0x00082108  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  CR_READ     [ dom:vcpu = 0x%(1)08x, CR# = %(2)d, value = 0x%(3)016x ]
 0x00082009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  CR_WRITE    [ dom:vcpu = 0x%(1)08x, CR# = %(2)d, value = 0x%(3)08x ]
+0x00082109  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  CR_WRITE    [ dom:vcpu = 0x%(1)08x, CR# = %(2)d, value = 0x%(3)016x ]
 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 ]
+0x0008200C  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  MSR_READ    [ dom:vcpu = 0x%(1)08x, MSR# = 0x%(2)08x, value = 0x%(3)016x ]
+0x0008200D  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  MSR_WRITE   [ dom:vcpu = 0x%(1)08x, MSR# = 0x%(2)08x, value = 0x%(3)016x ]
+0x0008200E  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  CPUID       [ dom:vcpu = 0x%(1)08x, func = 0x%(2)08x, eax = 0x%(3)08x, ebx = 0x%(4)08x, ecx=0x%(5)08x, edx = 0x%(6)08x ]
 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 ]
+0x00082014  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  INVLPG      [ dom:vcpu = 0x%(1)08x, is invlpga? = %(2)d, virt = 0x%(3)08x ]
+0x00082114  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  INVLPG      [ dom:vcpu = 0x%(1)08x, is invlpga? = %(2)d, virt = 0x%(3)016x ]
 0x00082015  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  MCE         [ dom:vcpu = 0x%(1)08x ]
 0x00082016  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  IO_ASSIST   [ dom:vcpu = 0x%(1)08x, data = 0x%(2)04x ]
 0x00082017  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  MMIO_ASSIST [ dom:vcpu = 0x%(1)08x, data = 0x%(2)04x ]
 0x00082018  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  CLTS        [ dom:vcpu = 0x%(1)08x ]
 0x00082019  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  LMSW        [ dom:vcpu = 0x%(1)08x, value = 0x%(2)08x ]
-0x00082020  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  PF_XEN64    [ dom:vcpu = 0x%(1)08x, errorcode = 0x%(2)02x, virt = 0x%(3)08x ]
+0x00082119  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  LMSW        [ dom:vcpu = 0x%(1)08x, value = 0x%(2)016x ]
+
+0x0010f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  page_grant_map      [ domid = %(1)d ]
+0x0010f002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  page_grant_unmap    [ domid = %(1)d ]
+0x0010f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  page_grant_transfer [ domid = %(1)d ]
+
+0x0020f001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hypercall  [ eip = 0x%(1)08x, eax = 0x%(2)08x ]
+0x0020f101  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  hypercall  [ rip = 0x%(1)016x, eax = 0x%(2)08x ]
+0x0020f003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  trap       [ eip = 0x%(1)08x, trapnr:error = 0x%(2)08x ]
+0x0020f103  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  trap       [ rip = 0x%(1)016x, trapnr:error = 0x%(2)08x ]
+0x0020f004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  page_fault [ eip = 0x%(1)08x, addr = 0x%(2)08x, error = 0x%(3)08x ]
+0x0020f104  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  page_fault [ rip = 0x%(1)16x, addr = 0x%(3)16x, error = 0x%(5)08x ]
diff --git a/tools/xentrace/xentrace_format b/tools/xentrace/xentrace_format
index 6399217bb6..d66cb74578 100644
--- a/tools/xentrace/xentrace_format
+++ b/tools/xentrace/xentrace_format
@@ -17,12 +17,12 @@ def usage():
           {event_id}{whitespace}{text format string}
 
           The textual format string may include format specifiers, such as:
-            %(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, %(5)d
+            %(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, ... 
           [ the 'd' format specifier outputs in decimal, alternatively 'x'
             will output in hexadecimal and 'o' will output in octal ]
 
           Which correspond to the CPU number, event ID, timestamp counter and
-          the 5 data fields from the trace record.  There should be one such
+          the 7 data fields from the trace record.  There should be one such
           rule for each type of event.
           
           Depending on your system and the volume of trace buffer data,
@@ -84,7 +84,7 @@ interrupted = 0
 defs = read_defs(arg[0])
 
 # structure of trace record (as output by xentrace):
-# HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I)
+# HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I) D6(I) D7(I)
 #
 # HDR consists of EVENT:28:, n_data:3:, tsc_in:1:
 # EVENT means Event ID
@@ -101,6 +101,8 @@ D2REC  = "II"
 D3REC  = "III"
 D4REC  = "IIII"
 D5REC  = "IIIII"
+D6REC  = "IIIIII"
+D7REC  = "IIIIIII"
 
 last_tsc = [0]
 
@@ -121,6 +123,8 @@ while not interrupted:
         d3 = 0
         d4 = 0
         d5 = 0
+        d6 = 0
+        d7 = 0
 
         tsc = 0
 
@@ -155,6 +159,16 @@ while not interrupted:
             if not line:
                 break
             (d1, d2, d3, d4, d5) = struct.unpack(D5REC, line)
+        if n_data == 6:
+            line = sys.stdin.read(struct.calcsize(D6REC))
+            if not line:
+                break
+            (d1, d2, d3, d4, d5, d6) = struct.unpack(D6REC, line)
+        if n_data == 7:
+            line = sys.stdin.read(struct.calcsize(D7REC))
+            if not line:
+                break
+            (d1, d2, d3, d4, d5, d6, d7) = struct.unpack(D7REC, line)
 
         # Event field is 28bit of 'uint32_t' in header, not 'long'.
         event &= 0x0fffffff
@@ -191,7 +205,9 @@ while not interrupted:
                 '2'     : d2,
                 '3'     : d3,
                 '4'     : d4,
-                '5'     : d5    }
+                '5'     : d5,
+                '6'     : d6,
+                '7'     : d7    }
 
         try: