1.1 --- a/tools/xentrace/Makefile	Wed May 19 09:46:39 2004 +0000
     1.2 +++ b/tools/xentrace/Makefile	Wed May 19 21:46:26 2004 +0000
     1.3 @@ -1,6 +1,6 @@
     1.4  
     1.5  CC       = gcc
     1.6 -CFLAGS   = -Wall -O3 
     1.7 +CFLAGS   = -Wall -O3 -Werror
     1.8  CFLAGS  += -I../../xen/include/hypervisor-ifs
     1.9  CFLAGS  += -I../../xenolinux-sparse/include
    1.10  CFLAGS  += -I../xend/lib

     2.1 --- a/tools/xentrace/formats	Wed May 19 09:46:39 2004 +0000
     2.2 +++ b/tools/xentrace/formats	Wed May 19 21:46:26 2004 +0000
     2.3 @@ -1,14 +1,35 @@
     2.4 -0x00010000	CPU%(cpu)d 0x%(tsc)x sched_add_domain(0x%(3)08x)            [ dom id = 0x%(1)x%(2)08x   ]
     2.5 -0x00010001	CPU%(cpu)d 0x%(tsc)x sched_rem_domain(0x%08(3)x)            [ dom id = 0x%(1)x%(2)08x   ]
     2.6 -0x00010002	CPU%(cpu)d 0x%(tsc)x __wake_up(0x%(3)08x)                   [ dom id = 0x%(1)x%(2)08x   ]
     2.7 -0x00010003	CPU%(cpu)d 0x%(tsc)x do_block()                             [ current = 0x%(2)08x         ]
     2.8 -0x00010004	CPU%(cpu)d 0x%(tsc)x do_yield()		                    [ current = %(2)08x         ]
     2.9 -0x00010005	CPU%(cpu)d 0x%(tsc)x do_set_timer_op(0x%(4)08x, 0x%(5)08x)  [ current = 0x%(3)08x ]
    2.10 -0x00010006	CPU%(cpu)d 0x%(tsc)x sched_ctl(0x%(1)08x)
    2.11 -0x00010007	CPU%(cpu)d 0x%(tsc)x sched_adjdom(params)                   [ dom id = 0x%(1)x%(2)08x   ]
    2.12 -0x00010008	CPU%(cpu)d 0x%(tsc)x __reschedule(0x%(3)08x)                [ dom id = 0x%(1)x%(2)08x   ]
    2.13 -0x00010009	CPU%(cpu)d 0x%(tsc)x switching to task_struct 0x%(1)08x     [ dom id = 0x%(1)x     ]
    2.14 -0x0001000A	CPU%(cpu)d 0x%(tsc)x s_timer_fn(unused)
    2.15 -0x0001000B	CPU%(cpu)d 0x%(tsc)x t_timer_fn(unused)
    2.16 -0x0001000C	CPU%(cpu)d 0x%(tsc)x dom_timer_fn(data)
    2.17 -0x0001000D	CPU%(cpu)d 0x%(tsc)x fallback_timer_fn(unused)
    2.18 +#0x00010000	CPU%(cpu)d %(tsc).6f sched_add_domain(0x%(3)08x)            [ dom id = 0x%(1)x%(2)08x   ]
    2.19 +#0x00010001	CPU%(cpu)d %(tsc).6f sched_rem_domain(0x%08(3)x)            [ dom id = 0x%(1)x%(2)08x   ]
    2.20 +#0x00010002	CPU%(cpu)d %(tsc).6f __wake_up(0x%(3)08x)                   [ dom id = 0x%(1)x%(2)08x   ]
    2.21 +#0x00010003	CPU%(cpu)d %(tsc).6f do_block()                             [ current = 0x%(2)08x         ]
    2.22 +#0x00010004	CPU%(cpu)d %(tsc).6f do_yield()		                    [ current = %(2)08x         ]
    2.23 +#0x00010005	CPU%(cpu)d %(tsc).6f do_set_timer_op(0x%(4)08x, 0x%(5)08x)  [ current = 0x%(3)08x ]
    2.24 +#0x00010006	CPU%(cpu)d %(tsc).6f sched_ctl(0x%(1)08x)
    2.25 +#0x00010007	CPU%(cpu)d %(tsc).6f sched_adjdom(params)                   [ dom id = 0x%(1)x%(2)08x   ]
    2.26 +#0x00010008	CPU%(cpu)d %(tsc).6f __reschedule(0x%(3)08x)                [ dom id = 0x%(1)x%(2)08x   ]
    2.27 +#0x00010009	CPU%(cpu)d %(tsc).6f switching to task_struct 0x%(1)08x     [ dom id = 0x%(1)x     ]
    2.28 +#0x0001000A	CPU%(cpu)d %(tsc).6f s_timer_fn(unused)
    2.29 +#0x0001000B	CPU%(cpu)d %(tsc).6f t_timer_fn(unused)
    2.30 +#0x0001000C	CPU%(cpu)d %(tsc).6f dom_timer_fn(data)
    2.31 +#0x0001000D	CPU%(cpu)d %(tsc).6f fallback_timer_fn(unused)
    2.32 +
    2.33 +
    2.34 +0x00020008	CPU%(cpu)d %(tsc).6f enter: dom0_create_dom ( )
    2.35 +0x00030008	CPU%(cpu)d %(tsc).6f leave: dom0_create_dom ( )
    2.36 +
    2.37 +0x00020009	CPU%(cpu)d %(tsc).6f enter: dom0_destroy_dom ( dom=0x%(2)x )
    2.38 +0x00030009	CPU%(cpu)d %(tsc).6f leave: dom0_destroy_dom ( dom=0x%(2)x ) = %(1)d
    2.39 +
    2.40 +0x0002000A	CPU%(cpu)d %(tsc).6f enter: dom0_start_dom ( dom=0x%(2)x )
    2.41 +0x0003000A	CPU%(cpu)d %(tsc).6f leave: dom0_start_dom ( dom=0x%(2)x ) = %(1)d
    2.42 +0x0002000B	CPU%(cpu)d %(tsc).6f enter: dom0_stop_dom ( dom=0x%(2)x )
    2.43 +0x0003000B	CPU%(cpu)d %(tsc).6f leave: dom0_stop_dom ( dom=0x%(2)x ) = %(1)d
    2.44 +0x0002000C	CPU%(cpu)d %(tsc).6f enter: dom0_getinfo ( dom=0x%(2)x )
    2.45 +0x0003000C	CPU%(cpu)d %(tsc).6f leave: dom0_getinfo ( dom=0x%(2)x ) = %(1)d
    2.46 +0x0002000D	CPU%(cpu)d %(tsc).6f enter: dom0_build ( dom=0x%(2)x )
    2.47 +0x0003000D	CPU%(cpu)d %(tsc).6f leave: dom0_build ( dom=0x%(2)x ) = %(1)d
    2.48 +
    2.49 +0x00020019	CPU%(cpu)d %(tsc).6f enter: dom0_shadow_op ( dom=0x%(2)x, %(3)d )
    2.50 +0x00030019	CPU%(cpu)d %(tsc).6f leave: dom0_shadow_op ( dom=0x%(2)x, %(3)d  ) = %(1)d
    2.51 +
    2.52 +#0x0		CPU%(cpu)d %(tsc).6f %(event)x

     3.1 --- a/tools/xentrace/xentrace.c	Wed May 19 09:46:39 2004 +0000
     3.2 +++ b/tools/xentrace/xentrace.c	Wed May 19 21:46:26 2004 +0000
     3.3 @@ -227,10 +227,10 @@ struct t_rec **init_rec_ptrs(unsigned lo
     3.4   * trace buffer.  Each entry in this table corresponds to the tail index for a
     3.5   * particular trace buffer.
     3.6   */
     3.7 -int *init_tail_idxs(struct t_buf **bufs, unsigned int num)
     3.8 +unsigned long *init_tail_idxs(struct t_buf **bufs, unsigned int num)
     3.9  {
    3.10      int i;
    3.11 -    int *tails = calloc(num, sizeof(unsigned int));
    3.12 +    unsigned long *tails = calloc(num, sizeof(unsigned int));
    3.13   
    3.14      if ( tails == NULL )
    3.15      {
    3.16 @@ -276,16 +276,19 @@ unsigned int get_num_cpus()
    3.17   */
    3.18  int monitor_tbufs(FILE *logfile)
    3.19  {
    3.20 -    int i, j;
    3.21 +    int i;
    3.22 +
    3.23      void *tbufs_mapped;          /* pointer to where the tbufs are mapped    */
    3.24      struct t_buf **meta;         /* pointers to the trace buffer metadata    */
    3.25      struct t_rec **data;         /* pointers to the trace buffer data areas
    3.26                                    * where they are mapped into user space.   */
    3.27 -    int *tails;                  /* store tail indexes for the trace buffers */
    3.28 +    unsigned long *cons;         /* store tail indexes for the trace buffers */
    3.29      unsigned long tbufs_phys;    /* physical address of the tbufs            */
    3.30      unsigned int  num;           /* number of trace buffers / logical CPUS   */
    3.31      unsigned long size;          /* size of a single trace buffer            */
    3.32  
    3.33 +    int size_in_recs;
    3.34 +
    3.35      /* get number of logical CPUs (and therefore number of trace buffers) */
    3.36      num = get_num_cpus();
    3.37  
    3.38 @@ -293,39 +296,32 @@ int monitor_tbufs(FILE *logfile)
    3.39      get_tbufs(&tbufs_phys, &size);
    3.40      tbufs_mapped = map_tbufs(tbufs_phys, num, size);
    3.41  
    3.42 +    size_in_recs = (size / sizeof(struct t_rec) )-1;
    3.43 +
    3.44      /* build arrays of convenience ptrs */
    3.45      meta  = init_bufs_ptrs (tbufs_mapped, num, size);
    3.46      data  = init_rec_ptrs  (tbufs_phys, tbufs_mapped, meta, num);
    3.47 -    tails = init_tail_idxs (meta, num);
    3.48 +    cons  = init_tail_idxs (meta, num);
    3.49  
    3.50      /* now, scan buffers for events */
    3.51      while ( !interrupted )
    3.52      {
    3.53          for ( i = 0; ( i < num ) && !interrupted; i++ )
    3.54 -        {
    3.55 -            signed long newdata = meta[i]->head - tails[i];
    3.56 -            signed long prewrap = newdata;
    3.57 -
    3.58 -	    /* correct newdata and prewrap in case of a pointer wrap */
    3.59 -            if ( newdata < 0 )
    3.60 -            {
    3.61 -                newdata += meta[i]->size;
    3.62 -                prewrap  = meta[i]->size - tails[i];
    3.63 -            }
    3.64 +        {	    
    3.65 +/*	    printf("XX%d: cons=%ld head=%ld  %p\n", i,
    3.66 +		   cons[i], meta[i]->head, data[i] + (cons[i] % size_in_recs) );
    3.67 +		   */
    3.68 +	    while( cons[i] < meta[i]->head )
    3.69 +	    {
    3.70 +/*
    3.71 +		if( (cons[i] % 6  ) == 0 )
    3.72 +		    printf("%d: cons=%ld head=%ld  %p\n", i,
    3.73 +		       cons[i], meta[i]->head, data[i] + (cons[i] % size_in_recs) );
    3.74 +		       */
    3.75 +		write_rec(i, data[i] + (cons[i] % size_in_recs), logfile);
    3.76 +		cons[i]++;
    3.77 +	    }
    3.78  
    3.79 -            if ( newdata >= opts.new_data_thresh )
    3.80 -            {
    3.81 -                /* output pre-wrap data */
    3.82 -                for(j = 0; j < prewrap; j++)
    3.83 -                    write_rec(i, data[i] + tails[i] + j, logfile);
    3.84 -                
    3.85 -                /* output post-wrap data, if any */                    
    3.86 -                for(j = 0; j < (newdata - prewrap); j++)
    3.87 -                    write_rec(i, data[i] + j, logfile);  
    3.88 -                
    3.89 -                tails[i] += newdata;
    3.90 -                if(tails[i] >= meta[i]->size) tails[i] = 0;
    3.91 -            }
    3.92          }
    3.93          nanosleep(&opts.poll_sleep, NULL);
    3.94      }
    3.95 @@ -333,7 +329,7 @@ int monitor_tbufs(FILE *logfile)
    3.96      /* cleanup */
    3.97      free(meta);
    3.98      free(data);
    3.99 -    free(tails);
   3.100 +    free(cons);
   3.101      /* don't need to munmap - cleanup is automatic */
   3.102      fclose(logfile);
   3.103  

     4.1 --- a/tools/xentrace/xentrace_format	Wed May 19 09:46:39 2004 +0000
     4.2 +++ b/tools/xentrace/xentrace_format	Wed May 19 21:46:26 2004 +0000
     4.3 @@ -4,7 +4,7 @@
     4.4  
     4.5  # Program for reformatting trace buffer output according to user-supplied rules
     4.6  
     4.7 -import re, sys, string, signal, struct
     4.8 +import re, sys, string, signal, struct, os, getopt
     4.9  
    4.10  def usage():
    4.11      print >> sys.stderr, \
    4.12 @@ -43,6 +43,9 @@ def read_defs(defs_file):
    4.13          line = fd.readline()
    4.14          if not line:
    4.15              break
    4.16 +	
    4.17 +	if line[0] == '#' or line[0] == '\n':
    4.18 +	    continue
    4.19          
    4.20          m = reg.match(line)
    4.21  
    4.22 @@ -58,29 +61,61 @@ def sighand(x,y):
    4.23  
    4.24  ##### Main code
    4.25  
    4.26 +mhz = 0
    4.27 +
    4.28  if len(sys.argv) < 2:
    4.29      usage()
    4.30  
    4.31 +try:
    4.32 +    opts, arg = getopt.getopt(sys.argv[1:], "c:" )
    4.33 +
    4.34 +    for opt in opts:
    4.35 +	if opt[0] == '-c' : mhz = int(opt[1])
    4.36 +
    4.37 +except getopt.GetoptError:
    4.38 +    usage()
    4.39 +
    4.40 +print mhz
    4.41 +
    4.42  signal.signal(signal.SIGTERM, sighand)
    4.43  signal.signal(signal.SIGHUP,  sighand)
    4.44  signal.signal(signal.SIGINT,  sighand)
    4.45  
    4.46  interrupted = 0
    4.47  
    4.48 -defs = read_defs(sys.argv[1])
    4.49 +defs = read_defs(arg[0])
    4.50 +
    4.51 +print defs
    4.52  
    4.53  # structure of trace record + prepended CPU id (as output by xentrace):
    4.54  # CPU(I) TSC(Q) EVENT(L) D1(L) D2(L) D3(L) D4(L) D5(L)
    4.55  TRCREC = "IQLLLLLL"
    4.56  
    4.57 +last_tsc = [0,0,0,0,0,0,0,0]
    4.58 +
    4.59 +i=0
    4.60 +
    4.61  while not interrupted:
    4.62      try:
    4.63 +	i=i+1
    4.64          line = sys.stdin.read(struct.calcsize(TRCREC))
    4.65          if not line:
    4.66              break
    4.67  
    4.68          (cpu, tsc, event, d1, d2, d3, d4, d5) = struct.unpack(TRCREC, line)
    4.69  
    4.70 +	#tsc = (tscH<<32) | tscL
    4.71 +
    4.72 +	#print i, tsc
    4.73 +
    4.74 +	if tsc < last_tsc[cpu]:
    4.75 +	    print "TSC stepped backward cpu %d !  %d %d" % (cpu,tsc,last_tsc[cpu])
    4.76 +
    4.77 +	last_tsc[cpu] = tsc
    4.78 +
    4.79 +	if mhz:
    4.80 +	    tsc = tsc / (mhz*1000000.0)
    4.81 +
    4.82          args = {'cpu'   : cpu,
    4.83                  'tsc'   : tsc,
    4.84                  'event' : event,
    4.85 @@ -90,8 +125,15 @@ while not interrupted:
    4.86                  '4'     : d4,
    4.87                  '5'     : d5    }
    4.88  
    4.89 -        if defs.has_key(str(event)): print defs[str(event)] % args
    4.90 -        # silently skip lines we don't have a format for - a 'complain' option
    4.91 -        # should be added if needed
    4.92 +	try:
    4.93 +
    4.94 +	    if defs.has_key(str(event)): 
    4.95 +		print defs[str(event)] % args
    4.96 +	    else: 
    4.97 +		if defs.has_key(str(0)): print defs[str(0)] % args
    4.98 +	except TypeError:
    4.99 +	    print defs[str(event)]
   4.100 +	    print args
   4.101 +	    
   4.102  
   4.103      except IOError, struct.error: sys.exit()

     5.1 --- a/xen/common/dom0_ops.c	Wed May 19 09:46:39 2004 +0000
     5.2 +++ b/xen/common/dom0_ops.c	Wed May 19 21:46:26 2004 +0000
     5.3 @@ -22,8 +22,8 @@
     5.4  #include <hypervisor-ifs/sched_ctl.h>
     5.5  
     5.6  
     5.7 -#define TRC_DOM0OP_START_BASE   0x00020000
     5.8 -#define TRC_DOM0OP_FINISH_BASE  0x00030000
     5.9 +#define TRC_DOM0OP_ENTER_BASE  0x00020000
    5.10 +#define TRC_DOM0OP_LEAVE_BASE  0x00030000
    5.11  
    5.12  
    5.13  extern unsigned int alloc_new_dom_mem(struct task_struct *, unsigned int);
    5.14 @@ -64,7 +64,7 @@ long do_dom0_op(dom0_op_t *u_dom0_op)
    5.15          return -EACCES;
    5.16      }
    5.17  
    5.18 -    TRACE_5D( TRC_DOM0OP_START_BASE + op->cmd, 
    5.19 +    TRACE_5D( TRC_DOM0OP_ENTER_BASE + op->cmd, 
    5.20  	 0, op->u.dummy[0], op->u.dummy[1], op->u.dummy[2], op->u.dummy[3] );
    5.21  
    5.22      switch ( op->cmd )
    5.23 @@ -668,7 +668,7 @@ long do_dom0_op(dom0_op_t *u_dom0_op)
    5.24  
    5.25      }
    5.26  
    5.27 -    TRACE_5D( TRC_DOM0OP_FINISH_BASE + op->cmd, ret,
    5.28 +    TRACE_5D( TRC_DOM0OP_LEAVE_BASE + op->cmd, ret,
    5.29  	 op->u.dummy[0], op->u.dummy[1], op->u.dummy[2], op->u.dummy[3]  );
    5.30  
    5.31  

     6.1 --- a/xen/common/trace.c	Wed May 19 09:46:39 2004 +0000
     6.2 +++ b/xen/common/trace.c	Wed May 19 21:46:26 2004 +0000
     6.3 @@ -27,7 +27,6 @@
     6.4  #include <xen/sched.h>
     6.5  #include <xen/slab.h>
     6.6  #include <xen/smp.h>
     6.7 -#include <xen/spinlock.h>
     6.8  #include <xen/trace.h>
     6.9  #include <xen/errno.h>
    6.10  #include <asm/atomic.h>
    6.11 @@ -86,7 +85,6 @@ void init_trace_bufs(void)
    6.12          /* For use in Xen. */
    6.13          buf->vdata    = (struct t_rec *)(buf+1);
    6.14          buf->head_ptr = buf->vdata;
    6.15 -        spin_lock_init(&buf->lock);
    6.16          
    6.17          /* For use in user space. */
    6.18          buf->data = (struct t_rec *)__pa(buf->vdata);

     7.1 --- a/xen/include/hypervisor-ifs/trace.h	Wed May 19 09:46:39 2004 +0000
     7.2 +++ b/xen/include/hypervisor-ifs/trace.h	Wed May 19 21:46:26 2004 +0000
     7.3 @@ -20,13 +20,12 @@ struct t_buf {
     7.4      struct t_rec *data;     /* pointer to data area.  physical address
     7.5                               * for convenience in user space code            */
     7.6  
     7.7 -    unsigned int size;      /* size of the data area, in t_recs              */
     7.8 -    unsigned int head;      /* array index of the most recent record         */
     7.9 +    unsigned long size;      /* size of the data area, in t_recs              */
    7.10 +    unsigned long head;      /* array index of the most recent record         */
    7.11  
    7.12  #ifdef __KERNEL__
    7.13      struct t_rec *head_ptr; /* pointer to the head record                    */
    7.14      struct t_rec *vdata;    /* virtual address pointer to data               */
    7.15 -    spinlock_t lock;        /* ensure mutually exlusive access (for inserts) */
    7.16  #endif
    7.17  
    7.18      /* never add anything here - the kernel stuff must be the last elements */

     8.1 --- a/xen/include/xen/trace.h	Wed May 19 09:46:39 2004 +0000
     8.2 +++ b/xen/include/xen/trace.h	Wed May 19 21:46:26 2004 +0000
     8.3 @@ -61,11 +61,13 @@ static inline int trace(u32 event, u32 d
     8.4      if ( !tb_init_done )
     8.5          return -1;
     8.6  
     8.7 +
     8.8      buf = t_bufs[smp_processor_id()];
     8.9 +
    8.10 +    local_irq_save(flags);
    8.11 +
    8.12      rec = buf->head_ptr;
    8.13  
    8.14 -    spin_lock_irqsave(&buf->lock, flags);
    8.15 -
    8.16      rdtscll(rec->cycles);
    8.17      rec->event = event;
    8.18      rec->d1 = d1;
    8.19 @@ -76,18 +78,12 @@ static inline int trace(u32 event, u32 d
    8.20  
    8.21      wmb(); /* above must be visible before reader sees index updated */
    8.22  
    8.23 -    if ( likely(buf->head_ptr < (buf->vdata + buf->size - 1)) )
    8.24 -    {
    8.25 -        buf->head_ptr++;
    8.26 -        buf->head++;
    8.27 -    }
    8.28 -    else
    8.29 -    {
    8.30 -        buf->head = 0;
    8.31 +    buf->head_ptr++;
    8.32 +    buf->head++;
    8.33 +    if ( buf->head_ptr == (buf->vdata + (buf->size-1)) )
    8.34          buf->head_ptr = buf->vdata;
    8.35 -    }
    8.36  
    8.37 -    spin_unlock_irqrestore(&buf->lock, flags);
    8.38 +    local_irq_restore(flags);
    8.39      
    8.40      return 0;
    8.41  }