Xen tracing cleanups and fixes.

Signed-off-by: Keir Fraser <keir@xensource.com>

5 files changed, 349 insertions, 382 deletions

diff --git a/tools/xenmon/xenbaked.c b/tools/xenmon/xenbaked.c
index 1587016335..27125a3142 100644
--- a/tools/xenmon/xenbaked.c
+++ b/tools/xenmon/xenbaked.c
@@ -12,7 +12,8 @@
  * Authors: Diwaker Gupta, diwaker.gupta@hp.com
  *          Rob Gardner, rob.gardner@hp.com
  *          Lucy Cherkasova, lucy.cherkasova.hp.com
- * Much code based on xentrace, authored by Mark Williamson, mark.a.williamson@intel.com
+ * Much code based on xentrace, authored by Mark Williamson, 
+ * mark.a.williamson@intel.com
  * Date:   November, 2005
  * 
  *  This program is free software; you can redistribute it and/or modify
@@ -107,31 +108,31 @@ int NCPU = 0;
 
 void init_current(int ncpu)
 {
-  running = calloc(ncpu, sizeof(int));
-  NCPU = ncpu;
-  printf("Initialized with %d %s\n", ncpu, (ncpu == 1) ? "cpu" : "cpu's");
+    running = calloc(ncpu, sizeof(int));
+    NCPU = ncpu;
+    printf("Initialized with %d %s\n", ncpu, (ncpu == 1) ? "cpu" : "cpu's");
 }
 
 int is_current(int domain, int cpu)
 {
-  //  int i;
+    //  int i;
   
-  //  for (i=0; i<NCPU; i++)
+    //  for (i=0; i<NCPU; i++)
     if (running[cpu] == domain)
-      return 1;
-  return 0;
+        return 1;
+    return 0;
 }
 
 
 // return the domain that's currently running on the given cpu
 int current(int cpu)
 {
-  return running[cpu];
+    return running[cpu];
 }
 
 void set_current(int cpu, int domain)
 {
-  running[cpu] = domain;
+    running[cpu] = domain;
 }
 
 
@@ -145,7 +146,7 @@ void close_handler(int signal)
 void dump_record(int cpu, struct t_rec *x)
 {
     printf("record: cpu=%x, tsc=%lx, event=%x, d1=%lx\n", 
-            cpu, x->cycles, x->event, x->data[0]);
+           cpu, x->cycles, x->event, x->data[0]);
 }
 #endif
 
@@ -198,15 +199,15 @@ void check_gotten_sum(void)
     int i;
 
     for (i=0; i<NCPU; i++) {
-      new_qos = cpu_qos_data[i];
-      ns = billion;
-      sum = total_ns_gotten(&ns);
-
-      printf("[cpu%d] ns_gotten over all domains = %lldns, over %lldns\n",
-	      i, sum, ns);
-      percent = (double) sum;
-      percent = (100.0*percent) / (double)ns;
-      printf(" ==> ns_gotten = %7.3f%%\n", percent);
+        new_qos = cpu_qos_data[i];
+        ns = billion;
+        sum = total_ns_gotten(&ns);
+
+        printf("[cpu%d] ns_gotten over all domains = %lldns, over %lldns\n",
+               i, sum, ns);
+        percent = (double) sum;
+        percent = (100.0*percent) / (double)ns;
+        printf(" ==> ns_gotten = %7.3f%%\n", percent);
     }
 #endif
 }
@@ -229,7 +230,7 @@ void dump_stats(void)
     }
 
     printf("processed %d total records in %d seconds (%ld per second)\n",
-            rec_count, (int)run_time, rec_count/run_time);
+           rec_count, (int)run_time, rec_count/run_time);
 
     printf("woke up %d times in %d seconds (%ld per second)\n", wakeups,
 	   (int) run_time, wakeups/run_time);
@@ -261,56 +262,56 @@ int xce_handle = -1;
 /* Stolen from xenstore code */
 int eventchn_init(void)
 {
-  int rc;
+    int rc;
   
-  // to revert to old way:
-  if (0)
-    return -1;
+    // to revert to old way:
+    if (0)
+        return -1;
   
-  xce_handle = xc_evtchn_open();
+    xce_handle = xc_evtchn_open();
 
-  if (xce_handle < 0)
-    perror("Failed to open evtchn device");
+    if (xce_handle < 0)
+        perror("Failed to open evtchn device");
   
-  if ((rc = xc_evtchn_bind_virq(xce_handle, VIRQ_TBUF)) == -1)
-    perror("Failed to bind to domain exception virq port");
-  virq_port = rc;
+    if ((rc = xc_evtchn_bind_virq(xce_handle, VIRQ_TBUF)) == -1)
+        perror("Failed to bind to domain exception virq port");
+    virq_port = rc;
   
-  return xce_handle;
+    return xce_handle;
 }
 
 void wait_for_event(void)
 {
-  int ret;
-  fd_set inset;
-  evtchn_port_t port;
-  struct timeval tv;
-  int evtchn_fd;
+    int ret;
+    fd_set inset;
+    evtchn_port_t port;
+    struct timeval tv;
+    int evtchn_fd;
   
-  if (xce_handle < 0) {
-    nanosleep(&opts.poll_sleep, NULL);
-    return;
-  }
-
-  evtchn_fd = xc_evtchn_fd(xce_handle);
-
-  FD_ZERO(&inset);
-  FD_SET(evtchn_fd, &inset);
-  tv.tv_sec = 1;
-  tv.tv_usec = 0;
-  // tv = millis_to_timespec(&opts.poll_sleep);
-  ret = select(evtchn_fd+1, &inset, NULL, NULL, &tv);
+    if (xce_handle < 0) {
+        nanosleep(&opts.poll_sleep, NULL);
+        return;
+    }
+
+    evtchn_fd = xc_evtchn_fd(xce_handle);
+
+    FD_ZERO(&inset);
+    FD_SET(evtchn_fd, &inset);
+    tv.tv_sec = 1;
+    tv.tv_usec = 0;
+    // tv = millis_to_timespec(&opts.poll_sleep);
+    ret = select(evtchn_fd+1, &inset, NULL, NULL, &tv);
   
-  if ( (ret == 1) && FD_ISSET(evtchn_fd, &inset)) {
-    if ((port = xc_evtchn_pending(xce_handle)) == -1)
-      perror("Failed to read from event fd");
+    if ( (ret == 1) && FD_ISSET(evtchn_fd, &inset)) {
+        if ((port = xc_evtchn_pending(xce_handle)) == -1)
+            perror("Failed to read from event fd");
     
-    //    if (port == virq_port)
-    //      printf("got the event I was looking for\r\n");
+        //    if (port == virq_port)
+        //      printf("got the event I was looking for\r\n");
 
-    if (xc_evtchn_unmask(xce_handle, port) == -1)
-      perror("Failed to write to event fd");
-  }
+        if (xc_evtchn_unmask(xce_handle, port) == -1)
+            perror("Failed to write to event fd");
+    }
 }
 
 static void get_tbufs(unsigned long *mfn, unsigned long *size)
@@ -336,9 +337,9 @@ static void get_tbufs(unsigned long *mfn, unsigned long *size)
 
 void disable_tracing(void)
 {
-  int xc_handle = xc_interface_open();
-  xc_tbuf_disable(xc_handle);  
-  xc_interface_close(xc_handle);
+    int xc_handle = xc_interface_open();
+    xc_tbuf_disable(xc_handle);  
+    xc_interface_close(xc_handle);
 }
 
 /**
@@ -387,7 +388,7 @@ struct t_buf *map_tbufs(unsigned long tbufs_mfn, unsigned int num,
  * mapped region containing all trace buffers.
  */
 struct t_buf **init_bufs_ptrs(void *bufs_mapped, unsigned int num,
-        unsigned long size)
+                              unsigned long size)
 {
     int i;
     struct t_buf **user_ptrs;
@@ -472,7 +473,7 @@ unsigned int get_num_cpus(void)
 int monitor_tbufs(void)
 {
     int i;
-    extern void process_record(int, struct t_rec *);
+    extern int process_record(int, struct t_rec *);
     extern void alloc_qos_data(int ncpu);
 
     void *tbufs_mapped;          /* pointer to where the tbufs are mapped    */
@@ -483,7 +484,7 @@ int monitor_tbufs(void)
     unsigned int  num;           /* number of trace buffers / logical CPUS   */
     unsigned long size;          /* size of a single trace buffer            */
 
-    int size_in_recs;
+    unsigned long data_size, rec_size;
 
     /* get number of logical CPUs (and therefore number of trace buffers) */
     num = get_num_cpus();
@@ -496,34 +497,32 @@ int monitor_tbufs(void)
     /* setup access to trace buffers */
     get_tbufs(&tbufs_mfn, &size);
 
-    //    printf("from dom0op: %ld, t_buf: %d, t_rec: %d\n",
-    //            size, sizeof(struct t_buf), sizeof(struct t_rec));
-
     tbufs_mapped = map_tbufs(tbufs_mfn, num, size);
 
-    size_in_recs = (size - sizeof(struct t_buf)) / sizeof(struct t_rec);
-    //    fprintf(stderr, "size_in_recs = %d\n", size_in_recs);
+    data_size = size - sizeof(struct t_buf);
 
     /* build arrays of convenience ptrs */
     meta  = init_bufs_ptrs (tbufs_mapped, num, size);
     data  = init_rec_ptrs(meta, num);
 
-    // Set up event channel for select()
-    if (eventchn_init() < 0) {
-      fprintf(stderr, "Failed to initialize event channel; Using POLL method\r\n");
-    }
+    if ( eventchn_init() < 0 )
+        fprintf(stderr, "Failed to initialize event channel; "
+                "Using POLL method\r\n");
 
     /* now, scan buffers for events */
     while ( !interrupted )
     {
-        for ( i = 0; ( i < num ) && !interrupted; i++ )
+        for ( i = 0; (i < num) && !interrupted; i++ )
+        {
             while ( meta[i]->cons != meta[i]->prod )
             {
                 rmb(); /* read prod, then read item. */
-                process_record(i, data[i] + meta[i]->cons % size_in_recs);
+                rec_size = process_record(
+                    i, data[i] + meta[i]->cons % data_size);
                 mb(); /* read item, then update cons. */
-                meta[i]->cons++;
+                meta[i]->cons += rec_size;
             }
+        }
 
 	wait_for_event();
 	wakeups++;
@@ -550,44 +549,44 @@ error_t cmd_parser(int key, char *arg, struct argp_state *state)
 
     switch ( key )
     {
-        case 't': /* set new records threshold for logging */
-            {
-                char *inval;
-                setup->new_data_thresh = strtol(arg, &inval, 0);
-                if ( inval == arg )
-                    argp_usage(state);
-            }
-            break;
+    case 't': /* set new records threshold for logging */
+    {
+        char *inval;
+        setup->new_data_thresh = strtol(arg, &inval, 0);
+        if ( inval == arg )
+            argp_usage(state);
+    }
+    break;
 
-        case 's': /* set sleep time (given in milliseconds) */
-            {
-                char *inval;
-                setup->poll_sleep = millis_to_timespec(strtol(arg, &inval, 0));
-                if ( inval == arg )
-                    argp_usage(state);
-            }
-            break;
+    case 's': /* set sleep time (given in milliseconds) */
+    {
+        char *inval;
+        setup->poll_sleep = millis_to_timespec(strtol(arg, &inval, 0));
+        if ( inval == arg )
+            argp_usage(state);
+    }
+    break;
 
-        case 'm': /* set ms_per_sample */
-            {
-                char *inval;
-                setup->ms_per_sample = strtol(arg, &inval, 0);
-                if ( inval == arg )
-                    argp_usage(state);
-            }
-            break;
+    case 'm': /* set ms_per_sample */
+    {
+        char *inval;
+        setup->ms_per_sample = strtol(arg, &inval, 0);
+        if ( inval == arg )
+            argp_usage(state);
+    }
+    break;
 
-        case ARGP_KEY_ARG:
-            {
-                if ( state->arg_num == 0 )
-                    setup->outfile = arg;
-                else
-                    argp_usage(state);
-            }
-            break;
+    case ARGP_KEY_ARG:
+    {
+        if ( state->arg_num == 0 )
+            setup->outfile = arg;
+        else
+            argp_usage(state);
+    }
+    break;
 
-        default:
-            return ARGP_ERR_UNKNOWN;
+    default:
+        return ARGP_ERR_UNKNOWN;
     }
 
     return 0;
@@ -614,27 +613,27 @@ void alloc_qos_data(int ncpu)
 
     for (n=0; n<ncpu; n++) {
 
-      for (i=0; i<sizeof(_new_qos_data); i=i+pgsize)
-          if ((write(qos_fd, dummy, pgsize)) != pgsize) {
-              PERROR(SHARED_MEM_FILE);
-              exit(2);
-          }
-
-      new_qos = (_new_qos_data *) mmap(0, sizeof(_new_qos_data), PROT_READ|PROT_WRITE, 
-				       MAP_SHARED, qos_fd, off);
-      off += i;
-      if (new_qos == NULL) {
-        PERROR("mmap");
-        exit(3);
-      }
-      //  printf("new_qos = %p\n", new_qos);
-      memset(new_qos, 0, sizeof(_new_qos_data));
-      new_qos->next_datapoint = 0;
-      advance_next_datapoint(0);
-      new_qos->structlen = i;
-      new_qos->ncpu = ncpu;
-      //      printf("structlen = 0x%x\n", i);
-      cpu_qos_data[n] = new_qos;
+        for (i=0; i<sizeof(_new_qos_data); i=i+pgsize)
+            if ((write(qos_fd, dummy, pgsize)) != pgsize) {
+                PERROR(SHARED_MEM_FILE);
+                exit(2);
+            }
+
+        new_qos = (_new_qos_data *) mmap(0, sizeof(_new_qos_data), PROT_READ|PROT_WRITE, 
+                                         MAP_SHARED, qos_fd, off);
+        off += i;
+        if (new_qos == NULL) {
+            PERROR("mmap");
+            exit(3);
+        }
+        //  printf("new_qos = %p\n", new_qos);
+        memset(new_qos, 0, sizeof(_new_qos_data));
+        new_qos->next_datapoint = 0;
+        advance_next_datapoint(0);
+        new_qos->structlen = i;
+        new_qos->ncpu = ncpu;
+        //      printf("structlen = 0x%x\n", i);
+        cpu_qos_data[n] = new_qos;
     }
     free(dummy);
     new_qos = NULL;
@@ -647,19 +646,19 @@ void alloc_qos_data(int ncpu)
 const struct argp_option cmd_opts[] =
 {
     { .name = "log-thresh", .key='t', .arg="l",
-        .doc =
-            "Set number, l, of new records required to trigger a write to output "
-            "(default " xstr(NEW_DATA_THRESH) ")." },
+      .doc =
+      "Set number, l, of new records required to trigger a write to output "
+      "(default " xstr(NEW_DATA_THRESH) ")." },
 
     { .name = "poll-sleep", .key='s', .arg="p",
-        .doc = 
-            "Set sleep time, p, in milliseconds between polling the trace buffer "
-            "for new data (default " xstr(POLL_SLEEP_MILLIS) ")." },
+      .doc = 
+      "Set sleep time, p, in milliseconds between polling the trace buffer "
+      "for new data (default " xstr(POLL_SLEEP_MILLIS) ")." },
 
     { .name = "ms_per_sample", .key='m', .arg="MS",
-        .doc = 
-            "Specify the number of milliseconds per sample "
-            " (default " xstr(MS_PER_SAMPLE) ")." },
+      .doc = 
+      "Specify the number of milliseconds per sample "
+      " (default " xstr(MS_PER_SAMPLE) ")." },
 
     {0}
 };
@@ -670,10 +669,10 @@ const struct argp parser_def =
     .parser = cmd_parser,
     //    .args_doc = "[output file]",
     .doc =
-        "Tool to capture and partially process Xen trace buffer data"
-        "\v"
-        "This tool is used to capture trace buffer data from Xen.  The data is "
-        "saved in a shared memory structure to be further processed by xenmon."
+    "Tool to capture and partially process Xen trace buffer data"
+    "\v"
+    "This tool is used to capture trace buffer data from Xen.  The data is "
+    "saved in a shared memory structure to be further processed by xenmon."
 };
 
 
@@ -716,101 +715,101 @@ int main(int argc, char **argv)
 
 void qos_init_domain(int domid, int idx)
 {
-  int i;
-
-  memset(&new_qos->domain_info[idx], 0, sizeof(_domain_info));
-  new_qos->domain_info[idx].last_update_time = global_now;
-  //  runnable_start_time[idx] = 0;
-  new_qos->domain_info[idx].runnable_start_time = 0; // invalidate
-  new_qos->domain_info[idx].in_use = 1;
-  new_qos->domain_info[idx].blocked_start_time = 0;
-  new_qos->domain_info[idx].id = domid;
-  if (domid == IDLE_DOMAIN_ID)
-    sprintf(new_qos->domain_info[idx].name, "Idle Task%d", global_cpu);
-  else
-    sprintf(new_qos->domain_info[idx].name, "Domain#%d", domid);
+    int i;
+
+    memset(&new_qos->domain_info[idx], 0, sizeof(_domain_info));
+    new_qos->domain_info[idx].last_update_time = global_now;
+    //  runnable_start_time[idx] = 0;
+    new_qos->domain_info[idx].runnable_start_time = 0; // invalidate
+    new_qos->domain_info[idx].in_use = 1;
+    new_qos->domain_info[idx].blocked_start_time = 0;
+    new_qos->domain_info[idx].id = domid;
+    if (domid == IDLE_DOMAIN_ID)
+        sprintf(new_qos->domain_info[idx].name, "Idle Task%d", global_cpu);
+    else
+        sprintf(new_qos->domain_info[idx].name, "Domain#%d", domid);
   
-  for (i=0; i<NSAMPLES; i++) {
-    new_qos->qdata[i].ns_gotten[idx] = 0;
-    new_qos->qdata[i].ns_allocated[idx] = 0;
-    new_qos->qdata[i].ns_waiting[idx] = 0;
-    new_qos->qdata[i].ns_blocked[idx] = 0;
-    new_qos->qdata[i].switchin_count[idx] = 0;
-    new_qos->qdata[i].io_count[idx] = 0;
-  }
+    for (i=0; i<NSAMPLES; i++) {
+        new_qos->qdata[i].ns_gotten[idx] = 0;
+        new_qos->qdata[i].ns_allocated[idx] = 0;
+        new_qos->qdata[i].ns_waiting[idx] = 0;
+        new_qos->qdata[i].ns_blocked[idx] = 0;
+        new_qos->qdata[i].switchin_count[idx] = 0;
+        new_qos->qdata[i].io_count[idx] = 0;
+    }
 }
 
 void global_init_domain(int domid, int idx) 
 {
-  int cpu;
-  _new_qos_data *saved_qos;
+    int cpu;
+    _new_qos_data *saved_qos;
   
-  saved_qos = new_qos;
+    saved_qos = new_qos;
   
-  for (cpu=0; cpu<NCPU; cpu++) {
-    new_qos = cpu_qos_data[cpu];
-    qos_init_domain(domid, idx);
-  }
-  new_qos = saved_qos;
+    for (cpu=0; cpu<NCPU; cpu++) {
+        new_qos = cpu_qos_data[cpu];
+        qos_init_domain(domid, idx);
+    }
+    new_qos = saved_qos;
 }
 
 
 // give index of this domain in the qos data array
 int indexof(int domid)
 {
-  int idx;
-  xc_dominfo_t dominfo[NDOMAINS];
-  int xc_handle, ndomains;
-  extern void qos_kill_thread(int domid);
+    int idx;
+    xc_dominfo_t dominfo[NDOMAINS];
+    int xc_handle, ndomains;
+    extern void qos_kill_thread(int domid);
   
-  if (domid < 0) {	// shouldn't happen
-    printf("bad domain id: %d\r\n", domid);
-    return 0;
-  }
+    if (domid < 0) {	// shouldn't happen
+        printf("bad domain id: %d\r\n", domid);
+        return 0;
+    }
 
-  for (idx=0; idx<NDOMAINS; idx++)
-    if ( (new_qos->domain_info[idx].id == domid) && new_qos->domain_info[idx].in_use)
-      return idx;
+    for (idx=0; idx<NDOMAINS; idx++)
+        if ( (new_qos->domain_info[idx].id == domid) && new_qos->domain_info[idx].in_use)
+            return idx;
 
-  // not found, make a new entry
-  for (idx=0; idx<NDOMAINS; idx++)
-    if (new_qos->domain_info[idx].in_use == 0) {
-      global_init_domain(domid, idx);
-      return idx;
-    }
+    // not found, make a new entry
+    for (idx=0; idx<NDOMAINS; idx++)
+        if (new_qos->domain_info[idx].in_use == 0) {
+            global_init_domain(domid, idx);
+            return idx;
+        }
+
+    // call domaininfo hypercall to try and garbage collect unused entries
+    xc_handle = xc_interface_open();
+    ndomains = xc_domain_getinfo(xc_handle, 0, NDOMAINS, dominfo);
+    xc_interface_close(xc_handle);
 
-  // call domaininfo hypercall to try and garbage collect unused entries
-  xc_handle = xc_interface_open();
-  ndomains = xc_domain_getinfo(xc_handle, 0, NDOMAINS, dominfo);
-  xc_interface_close(xc_handle);
-
-  // for each domain in our data, look for it in the system dominfo structure
-  // and purge the domain's data from our state if it does not exist in the
-  // dominfo structure
-  for (idx=0; idx<NDOMAINS; idx++) {
-    int domid = new_qos->domain_info[idx].id;
-    int jdx;
+    // for each domain in our data, look for it in the system dominfo structure
+    // and purge the domain's data from our state if it does not exist in the
+    // dominfo structure
+    for (idx=0; idx<NDOMAINS; idx++) {
+        int domid = new_qos->domain_info[idx].id;
+        int jdx;
     
-    for (jdx=0; jdx<ndomains; jdx++) {
-      if (dominfo[jdx].domid == domid)
-	break;
+        for (jdx=0; jdx<ndomains; jdx++) {
+            if (dominfo[jdx].domid == domid)
+                break;
+        }
+        if (jdx == ndomains)        // we didn't find domid in the dominfo struct
+            if (domid != IDLE_DOMAIN_ID) // exception for idle domain, which is not
+                // contained in dominfo
+                qos_kill_thread(domid);	// purge our stale data
     }
-    if (jdx == ndomains)        // we didn't find domid in the dominfo struct
-      if (domid != IDLE_DOMAIN_ID) // exception for idle domain, which is not
-	                           // contained in dominfo
-	qos_kill_thread(domid);	// purge our stale data
-  }
   
-  // look again for a free slot
-  for (idx=0; idx<NDOMAINS; idx++)
-    if (new_qos->domain_info[idx].in_use == 0) {
-      global_init_domain(domid, idx);
-      return idx;
-    }
+    // look again for a free slot
+    for (idx=0; idx<NDOMAINS; idx++)
+        if (new_qos->domain_info[idx].in_use == 0) {
+            global_init_domain(domid, idx);
+            return idx;
+        }
 
-  // still no space found, so bail
-  fprintf(stderr, "out of space in domain table, increase NDOMAINS\r\n");
-  exit(2);
+    // still no space found, so bail
+    fprintf(stderr, "out of space in domain table, increase NDOMAINS\r\n");
+    exit(2);
 }
 
 int domain_runnable(int domid)
@@ -879,25 +878,25 @@ void qos_update_thread(int cpu, int domid, uint64_t now)
     time_since_update = now - last_update_time;
 
     if (time_since_update < 0) {
-      // what happened here? either a timestamp wraparound, or more likely,
-      // a slight inconsistency among timestamps from various cpu's
-      if (-time_since_update < billion) {
-	// fairly small difference, let's just adjust 'now' to be a little
-	// beyond last_update_time
-	time_since_update = -time_since_update;
-      }
-      else if ( ((~0ULL - last_update_time) < billion) && (now < billion) ) {
-	// difference is huge, must be a wraparound
-	// last_update time should be "near" ~0ULL,
-	// and now should be "near" 0
-	time_since_update = now + (~0ULL - last_update_time);
-	printf("time wraparound\n");
-      }
-      else {
-	// none of the above, may be an out of order record
-	// no good solution, just ignore and update again later
-	return;
-      }
+        // what happened here? either a timestamp wraparound, or more likely,
+        // a slight inconsistency among timestamps from various cpu's
+        if (-time_since_update < billion) {
+            // fairly small difference, let's just adjust 'now' to be a little
+            // beyond last_update_time
+            time_since_update = -time_since_update;
+        }
+        else if ( ((~0ULL - last_update_time) < billion) && (now < billion) ) {
+            // difference is huge, must be a wraparound
+            // last_update time should be "near" ~0ULL,
+            // and now should be "near" 0
+            time_since_update = now + (~0ULL - last_update_time);
+            printf("time wraparound\n");
+        }
+        else {
+            // none of the above, may be an out of order record
+            // no good solution, just ignore and update again later
+            return;
+        }
     }
 	
     new_qos->domain_info[id].last_update_time = now;
@@ -985,7 +984,7 @@ void qos_switch_in(int cpu, int domid, uint64_t now, unsigned long ns_alloc, uns
 
     // count up page flips for dom0 execution
     if (domid == 0)
-      dom0_flips = 0;
+        dom0_flips = 0;
 }
 
 // called when the current thread is taken off the cpu
@@ -1011,8 +1010,8 @@ void qos_switch_out(int cpu, int domid, uint64_t now, unsigned long gotten)
 #if 0
     new_qos->qdata[n].ns_gotten[idx] += gotten;
     if (gotten > new_qos->qdata[n].ns_passed)
-      printf("inconsistency #257, diff = %lld\n",
-	    gotten - new_qos->qdata[n].ns_passed );
+        printf("inconsistency #257, diff = %lld\n",
+               gotten - new_qos->qdata[n].ns_passed );
 #endif
     new_qos->domain_info[idx].ns_oncpu_since_boot += gotten;
     new_qos->domain_info[idx].runnable_start_time = now;
@@ -1021,8 +1020,8 @@ void qos_switch_out(int cpu, int domid, uint64_t now, unsigned long gotten)
 
     // process dom0 page flips
     if (domid == 0)
-      if (dom0_flips == 0)
-	new_qos->qdata[n].flip_free_periods++;
+        if (dom0_flips == 0)
+            new_qos->qdata[n].flip_free_periods++;
 }
 
 // called when domain is put to sleep, may also be called
@@ -1047,11 +1046,11 @@ void qos_state_sleeping(int cpu, int domid, uint64_t now)
 // domain died, presume it's dead on all cpu's, not just mostly dead
 void qos_kill_thread(int domid)
 {
-  int cpu;
+    int cpu;
   
-  for (cpu=0; cpu<NCPU; cpu++) {
-    cpu_qos_data[cpu]->domain_info[indexof(domid)].in_use = 0;
-  }
+    for (cpu=0; cpu<NCPU; cpu++) {
+        cpu_qos_data[cpu]->domain_info[indexof(domid)].in_use = 0;
+    }
   
 }
 
@@ -1060,7 +1059,7 @@ void qos_kill_thread(int domid)
 // when thread is already runnable
 void qos_state_runnable(int cpu, int domid, uint64_t now)
 {
-   int idx;
+    int idx;
   
 
     qos_update_thread_stats(cpu, domid, now);
@@ -1080,79 +1079,85 @@ void qos_state_runnable(int cpu, int domid, uint64_t now)
 
 void qos_count_packets(domid_t domid, uint64_t now)
 {
-  int i, idx = indexof(domid);
-  _new_qos_data *cpu_data;
+    int i, idx = indexof(domid);
+    _new_qos_data *cpu_data;
 
-  for (i=0; i<NCPU; i++) {
-    cpu_data = cpu_qos_data[i];
-    if (cpu_data->domain_info[idx].in_use) {
-      cpu_data->qdata[cpu_data->next_datapoint].io_count[idx]++;
+    for (i=0; i<NCPU; i++) {
+        cpu_data = cpu_qos_data[i];
+        if (cpu_data->domain_info[idx].in_use) {
+            cpu_data->qdata[cpu_data->next_datapoint].io_count[idx]++;
+        }
     }
-  }
 
-  new_qos->qdata[new_qos->next_datapoint].io_count[0]++;
-  dom0_flips++;
+    new_qos->qdata[new_qos->next_datapoint].io_count[0]++;
+    dom0_flips++;
 }
 
 
-void process_record(int cpu, struct t_rec *r)
+int process_record(int cpu, struct t_rec *r)
 {
-  uint64_t now;
+    uint64_t now = 0;
+    uint32_t *extra_u32 = r->u.nocycles.extra_u32;
 
-  new_qos = cpu_qos_data[cpu];
+    new_qos = cpu_qos_data[cpu];
 
-  rec_count++;
+    rec_count++;
 
-  now = ((double)r->cycles) / (opts.cpu_freq / 1000.0);
+    if ( r->cycles_included )
+    {
+        now = ((uint64_t)r->u.cycles.cycles_hi << 32) | r->u.cycles.cycles_lo;
+        now = ((double)now) / (opts.cpu_freq / 1000.0);
+        extra_u32 = r->u.cycles.extra_u32;
+    }
 
-  global_now = now;
-  global_cpu = cpu;
+    global_now = now;
+    global_cpu = cpu;
 
-  log_event(r->event);
+    log_event(r->event);
 
-  switch (r->event) {
+    switch (r->event) {
 
-  case TRC_SCHED_SWITCH_INFPREV:
-    // domain data[0] just switched out and received data[1] ns of cpu time
-    qos_switch_out(cpu, r->data[0], now, r->data[1]);
-    //    printf("ns_gotten %ld\n", r->data[1]);
-    break;
+    case TRC_SCHED_SWITCH_INFPREV:
+        // domain data[0] just switched out and received data[1] ns of cpu time
+        qos_switch_out(cpu, extra_u32[0], now, extra_u32[1]);
+        //    printf("ns_gotten %ld\n", extra_u32[1]);
+        break;
     
-  case TRC_SCHED_SWITCH_INFNEXT:
-    // domain data[0] just switched in and
-    // waited data[1] ns, and was allocated data[2] ns of cpu time
-    qos_switch_in(cpu, r->data[0], now, r->data[2], r->data[1]);
-    break;
+    case TRC_SCHED_SWITCH_INFNEXT:
+        // domain data[0] just switched in and
+        // waited data[1] ns, and was allocated data[2] ns of cpu time
+        qos_switch_in(cpu, extra_u32[0], now, extra_u32[2], extra_u32[1]);
+        break;
     
-  case TRC_SCHED_DOM_ADD:
-    (void) indexof(r->data[0]);
-    break;
+    case TRC_SCHED_DOM_ADD:
+        (void) indexof(extra_u32[0]);
+        break;
     
-  case TRC_SCHED_DOM_REM:
-    qos_kill_thread(r->data[0]);
-    break;
+    case TRC_SCHED_DOM_REM:
+        qos_kill_thread(extra_u32[0]);
+        break;
     
-  case TRC_SCHED_SLEEP:
-    qos_state_sleeping(cpu, r->data[0], now);
-    break;
+    case TRC_SCHED_SLEEP:
+        qos_state_sleeping(cpu, extra_u32[0], now);
+        break;
     
-  case TRC_SCHED_WAKE:
-    qos_state_runnable(cpu, r->data[0], now);
-    break;
+    case TRC_SCHED_WAKE:
+        qos_state_runnable(cpu, extra_u32[0], now);
+        break;
     
-  case TRC_SCHED_BLOCK:
-    qos_state_sleeping(cpu, r->data[0], now);
-    break;
+    case TRC_SCHED_BLOCK:
+        qos_state_sleeping(cpu, extra_u32[0], now);
+        break;
     
-  case TRC_MEM_PAGE_GRANT_TRANSFER:
-    qos_count_packets(r->data[0], now);
-    break;
+    case TRC_MEM_PAGE_GRANT_TRANSFER:
+        qos_count_packets(extra_u32[0], now);
+        break;
     
-  default:
-    break;
-  }
-  new_qos = NULL;
-}
-
+    default:
+        break;
+    }
 
+    new_qos = NULL;
 
+    return 4 + (r->cycles_included ? 8 : 0) + (r->extra_u32 * 4);
+}
diff --git a/tools/xentrace/xentrace.c b/tools/xentrace/xentrace.c
index 29e6d15865..7c858b7702 100644
--- a/tools/xentrace/xentrace.c
+++ b/tools/xentrace/xentrace.c
@@ -102,7 +102,7 @@ void write_buffer(unsigned int cpu, unsigned char *start, int size,
     /* Write a CPU_BUF record on each buffer "window" written.  Wrapped
      * windows may involve two writes, so only write the record on the
      * first write. */
-    if(total_size)
+    if ( total_size != 0 )
     {
         struct {
             uint32_t header;
@@ -119,7 +119,8 @@ void write_buffer(unsigned int cpu, unsigned char *start, int size,
 
         written = write(outfd, &rec, sizeof(rec));
 
-        if(written!=sizeof(rec)) {
+        if ( written != sizeof(rec) )
+        {
             fprintf(stderr, "Cannot write cpu change (write returned %d)\n",
                     written);
             goto fail;
@@ -127,12 +128,15 @@ void write_buffer(unsigned int cpu, unsigned char *start, int size,
     }
 
     written = write(outfd, start, size);
-    if ( written != size ) {
+    if ( written != size )
+    {
         fprintf(stderr, "Write failed! (size %d, returned %d)\n",
                 size, written);
         goto fail;
     }
+
     return;
+
  fail:
     PERROR("Failed to write trace data");
     exit(EXIT_FAILURE);
@@ -337,7 +341,7 @@ int monitor_tbufs(int outfd)
     get_tbufs(&tbufs_mfn, &size);
     tbufs_mapped = map_tbufs(tbufs_mfn, num, size);
 
-    data_size = (size - sizeof(struct t_buf));
+    data_size = size - sizeof(struct t_buf);
 
     /* build arrays of convenience ptrs */
     meta  = init_bufs_ptrs(tbufs_mapped, num, size);
@@ -353,13 +357,13 @@ int monitor_tbufs(int outfd)
         for ( i = 0; (i < num) && !interrupted; i++ )
         {
             unsigned long start_offset, end_offset, window_size, cons, prod;
-            rmb(); /* read prod, then read item. */
                 
             /* Read window information only once. */
             cons = meta[i]->cons;
             prod = meta[i]->prod;
+            rmb(); /* read prod, then read item. */
             
-            if(cons == prod)
+            if ( cons == prod )
                 continue;
            
             assert(prod > cons);
@@ -368,7 +372,7 @@ int monitor_tbufs(int outfd)
             start_offset = cons % data_size;
             end_offset = prod % data_size;
 
-            if(end_offset > start_offset)
+            if ( end_offset > start_offset )
             {
                 /* If window does not wrap, write in one big chunk */
                 write_buffer(i, data[i]+start_offset,
@@ -382,7 +386,7 @@ int monitor_tbufs(int outfd)
                  * - first, start to the end of the buffer
                  * - second, start of buffer to end of window
                  */
-                write_buffer(i, data[i]+start_offset,
+                write_buffer(i, data[i] + start_offset,
                              data_size - start_offset,
                              window_size,
                              outfd);
diff --git a/xen/common/trace.c b/xen/common/trace.c
index 5209d1fb59..9e76f26605 100644
--- a/xen/common/trace.c
+++ b/xen/common/trace.c
@@ -233,7 +233,7 @@ static inline int calc_rec_size(int cycles, int extra)
 {
     int rec_size;
     rec_size = 4;
-    if(cycles)
+    if ( cycles )
         rec_size += 8;
     rec_size += extra;
     return rec_size;
@@ -254,10 +254,10 @@ static inline int __insert_record(struct t_buf *buf,
                                   int extra,
                                   int cycles,
                                   int rec_size,
-                                  unsigned char * extra_data) 
+                                  unsigned char *extra_data)
 {
     struct t_rec *rec;
-    unsigned char * dst;
+    unsigned char *dst;
     unsigned long extra_word = extra/sizeof(u32);
     int local_rec_size = calc_rec_size(cycles, extra);
 
@@ -266,7 +266,7 @@ static inline int __insert_record(struct t_buf *buf,
     /* Double-check once more that we have enough space.
      * Don't bugcheck here, in case the userland tool is doing
      * something stupid. */
-    if(calc_bytes_avail(buf) < rec_size )
+    if ( calc_bytes_avail(buf) < rec_size )
     {
         printk("%s: %u bytes left (%u - (%u - %u)) recsize %u.\n",
                __func__,
@@ -278,25 +278,22 @@ static inline int __insert_record(struct t_buf *buf,
     rmb();
 
     rec = (struct t_rec *)&this_cpu(t_data)[buf->prod % data_size];
-    rec->header = event;
-    rec->header |= extra_word << TRACE_EXTRA_SHIFT;
-    if(cycles) 
+    rec->event = event;
+    rec->extra_u32 = extra_word;
+    dst = (unsigned char *)rec->u.nocycles.extra_u32;
+    if ( (rec->cycles_included = cycles) != 0 )
     {
         u64 tsc = (u64)get_cycles();
-
-        rec->header |= TRC_HD_CYCLE_FLAG;
-        rec->u.cycles.cycles_lo = tsc & ((((u64)1)<<32)-1);
-        rec->u.cycles.cycles_hi = tsc >> 32;
-        dst = rec->u.cycles.data;
+        rec->u.cycles.cycles_lo = (uint32_t)tsc;
+        rec->u.cycles.cycles_hi = (uint32_t)(tsc >> 32);
+        dst = (unsigned char *)rec->u.cycles.extra_u32;
     } 
-    else
-        dst = rec->u.nocycles.data;
 
-    if(extra_data && extra)
+    if ( extra_data && extra )
         memcpy(dst, extra_data, extra);
 
     wmb();
-    buf->prod+=rec_size;
+    buf->prod += rec_size;
 
     return rec_size;
 }
@@ -305,24 +302,18 @@ static inline int insert_wrap_record(struct t_buf *buf, int size)
 {
     int space_left = calc_bytes_to_wrap(buf);
     unsigned long extra_space = space_left - sizeof(u32);
-    int cycles=0;
-
-    if(space_left > size)
-        printk("%s: space_left %d, size %d!\n",
-               __func__, space_left, size);
+    int cycles = 0;
 
     BUG_ON(space_left > size);
 
     /* We may need to add cycles to take up enough space... */
-    if((extra_space/sizeof(u32)) > TRACE_EXTRA_MAX)
+    if ( (extra_space/sizeof(u32)) > TRACE_EXTRA_MAX )
     {
         cycles = 1;
         extra_space -= sizeof(u64);
-        
         ASSERT((extra_space/sizeof(u32)) <= TRACE_EXTRA_MAX);
     }
 
-
     return __insert_record(buf,
                     TRC_TRACE_WRAP_BUFFER,
                     extra_space,
@@ -433,9 +424,9 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
      * avoid if we can.  So do the math, check it in debug versions, and
      * do a final check always if we happen to write a record.
      */
-    if(this_cpu(lost_records))
+    if ( this_cpu(lost_records) )
     {
-        if(LOST_REC_SIZE > bytes_to_wrap)
+        if ( LOST_REC_SIZE > bytes_to_wrap )
         {
             total_size += bytes_to_wrap;
             bytes_to_wrap = data_size;
@@ -443,7 +434,7 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
         else
         {
             bytes_to_wrap -= LOST_REC_SIZE;
-            if(bytes_to_wrap == 0)
+            if ( bytes_to_wrap == 0 )
                 bytes_to_wrap == data_size;
         }
         total_size += LOST_REC_SIZE;
@@ -451,7 +442,7 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
 
     ASSERT(bytes_to_wrap == calc_bytes_to_wrap(buf));
 
-    if(rec_size > bytes_to_wrap)
+    if ( rec_size > bytes_to_wrap )
     {
         total_size += bytes_to_wrap;
         bytes_to_wrap = data_size;
@@ -464,7 +455,7 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
     total_size += rec_size;
 
     /* Do we have enough space for everything? */
-    if(total_size > bytes_to_tail) 
+    if ( total_size > bytes_to_tail )
     {
         this_cpu(lost_records)++;
         local_irq_restore(flags);
@@ -476,9 +467,9 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
      */
     bytes_to_wrap = calc_bytes_to_wrap(buf);
 
-    if(this_cpu(lost_records))
+    if ( this_cpu(lost_records) )
     {
-        if(LOST_REC_SIZE > bytes_to_wrap)
+        if ( LOST_REC_SIZE > bytes_to_wrap )
         {
             insert_wrap_record(buf, LOST_REC_SIZE);
             bytes_to_wrap = data_size;
@@ -487,7 +478,7 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
         {
             bytes_to_wrap -= LOST_REC_SIZE;
             /* LOST_REC might line up perfectly with the buffer wrap */
-            if(bytes_to_wrap == 0)
+            if ( bytes_to_wrap == 0 )
                 bytes_to_wrap = data_size;
         }
         insert_lost_records(buf);
@@ -495,42 +486,20 @@ void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data)
 
     ASSERT(bytes_to_wrap == calc_bytes_to_wrap(buf));
 
-    if(rec_size > bytes_to_wrap)
-    {
+    if ( rec_size > bytes_to_wrap )
         insert_wrap_record(buf, rec_size);
-    } 
 
     /* Write the original record */
     __insert_record(buf, event, extra, cycles, rec_size, extra_data);
 
     local_irq_restore(flags);
 
-    /*
-     * Notify trace buffer consumer that we've crossed the high water mark.
-     *
-     */
+    /* Notify trace buffer consumer that we've crossed the high water mark. */
     if ( started_below_highwater
-         && ( (buf->prod - buf->cons) > t_buf_highwater ) )
+         && ((buf->prod - buf->cons) > t_buf_highwater) )
         raise_softirq(TRACE_SOFTIRQ);
 }
 
-
-void __trace_fixed(u32 event, unsigned long d1, unsigned long d2,
-           unsigned long d3, unsigned long d4, unsigned long d5)
-{
-    u32 extra_data[5];
-    
-    /* In a 64-bit hypervisor, this will truncate to 32 bits. */
-    extra_data[0]=d1;
-    extra_data[1]=d2;
-    extra_data[2]=d3;
-    extra_data[3]=d4;
-    extra_data[4]=d5;
-
-    __trace_var(event, 1/* include cycles */, sizeof(*extra_data)*5,
-              (unsigned char *)extra_data);
-}
-
 /*
  * Local variables:
  * mode: C
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index ecdce0c43d..a2d75ba2f2 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -103,23 +103,22 @@
 #define TRC_HVM_MMIO_ASSIST     (TRC_HVM_HANDLER + 0x17)
 #define TRC_HVM_CLTS            (TRC_HVM_HANDLER + 0x18)
 #define TRC_HVM_LMSW            (TRC_HVM_HANDLER + 0x19)
-#define TRC_HVM_PF_XEN64       (TRC_HVM_HANDLER + 0x20)
+#define TRC_HVM_PF_XEN64        (TRC_HVM_HANDLER + 0x20)
 
 /* This structure represents a single trace buffer record. */
 struct t_rec {
-    uint32_t header;           /* 31   : Cycles included?
-                                  30-28: # of extra words
-                                  27- 0: event ID                */
+    uint32_t event:28;
+    uint32_t extra_u32:3;         /* # entries in trailing extra_u32[] array */
+    uint32_t cycles_included:1;   /* u.cycles or u.no_cycles? */
     union {
         struct {
             uint32_t cycles_lo, cycles_hi; /* cycle counter timestamp */
-            unsigned char data[28];        /* event data items        */
+            uint32_t extra_u32[7];         /* event data items */
         } cycles;
         struct {
-            unsigned char data[28];        /* event data items        */
+            uint32_t extra_u32[7];         /* event data items */
         } nocycles;
-    }u;
-        
+    } u;
 };
 
 /*
diff --git a/xen/include/xen/trace.h b/xen/include/xen/trace.h
index 4bbb37d297..41db3f7dc6 100644
--- a/xen/include/xen/trace.h
+++ b/xen/include/xen/trace.h
@@ -33,18 +33,8 @@ void init_trace_bufs(void);
 /* used to retrieve the physical address of the trace buffers */
 int tb_control(struct xen_sysctl_tbuf_op *tbc);
 
-void __trace_fixed(u32 event, unsigned long d1, unsigned long d2,
-           unsigned long d3, unsigned long d4, unsigned long d5);
 void __trace_var(u32 event, int cycles, int extra, unsigned char *extra_data);
 
-static inline void trace_fixed(u32 event, unsigned long d1,
-                               unsigned long d2, unsigned long d3,
-                               unsigned long d4, unsigned long d5)
-{
-    if( unlikely(tb_init_done) )
-        __trace_fixed(event, d1, d2, d3, d4, d5);
-}
-
 static inline void trace_var(u32 event, int cycles, int extra,
                                unsigned char *extra_data)
 {