bitkeeper revision 1.122.1.10 (3e70a344_miNFwTDQHx7TSuaWoY4lA)

Merge ssh://rn212@gauntlet.cl.cam.ac.uk//usr/groups/xeno/BK/xeno.bk
into wyvis.research.intel-research.net:/home/rn/src/xeno/xeno.bk

8 files changed, 163 insertions, 123 deletions

diff --git a/BitKeeper/etc/logging_ok b/BitKeeper/etc/logging_ok
index 4998459b72..84541e8dec 100644
--- a/BitKeeper/etc/logging_ok
+++ b/BitKeeper/etc/logging_ok
@@ -10,5 +10,6 @@ kaf24@scramble.cl.cam.ac.uk
 kaf24@striker.cl.cam.ac.uk
 lynx@idefix.cl.cam.ac.uk
 rn@wyvis.camb.intel-research.net
+rn@wyvis.research.intel-research.net
 smh22@boulderdash.cl.cam.ac.uk
 smh22@uridium.cl.cam.ac.uk
diff --git a/xen/arch/i386/apic.c b/xen/arch/i386/apic.c
index 9b999df951..865a279d8c 100644
--- a/xen/arch/i386/apic.c
+++ b/xen/arch/i386/apic.c
@@ -48,6 +48,8 @@
 
 #include <xeno/ac_timer.h>
 
+#include <xeno/perfc.h>
+
 #undef APIC_TIME_TRACE
 #ifdef APIC_TIME_TRACE
 #define TRC(_x) _x
@@ -748,6 +750,7 @@ void smp_apic_timer_interrupt(struct pt_regs * regs)
 
 	/* call the local handler */
     irq_enter(cpu, 0);
+	perfc_incrc(apic_timer);
     smp_local_timer_interrupt(regs);
     irq_exit(cpu, 0);
 
diff --git a/xen/arch/i386/irq.c b/xen/arch/i386/irq.c
index e58fb8f2ad..312cfe7970 100644
--- a/xen/arch/i386/irq.c
+++ b/xen/arch/i386/irq.c
@@ -36,6 +36,7 @@
 #include <asm/pgalloc.h>
 #include <xeno/delay.h>
 
+#include <xeno/perfc.h>
 
 /*
  * Linux has a controller-independent x86 interrupt architecture.
@@ -469,6 +470,11 @@ asmlinkage unsigned int do_IRQ(struct pt_regs regs)
     struct irqaction * action;
     unsigned int status;
 
+    u32     cc_start, cc_end;
+
+    perfc_incra(irqs, cpu);
+    rdtscl(cc_start);
+
     spin_lock(&desc->lock);
     desc->handler->ack(irq);
     /*
@@ -530,6 +536,9 @@ asmlinkage unsigned int do_IRQ(struct pt_regs regs)
     if (softirq_pending(cpu))
         do_softirq();
 
+    rdtscl(cc_end);
+    perfc_adda(irq_time, cpu, cc_end - cc_start);
+
     return 1;
 }
 
diff --git a/xen/common/ac_timer.c b/xen/common/ac_timer.c
index 8f65ff7093..dc70de4e0c 100644
--- a/xen/common/ac_timer.c
+++ b/xen/common/ac_timer.c
@@ -25,7 +25,8 @@
 #include <xeno/lib.h>
 #include <xeno/config.h>
 #include <xeno/smp.h>
-#include <xeno/init.h>
+
+#include <xeno/perfc.h>
 
 #include <xeno/time.h>
 #include <xeno/ac_timer.h>
@@ -34,10 +35,6 @@
 #include <asm/system.h>
 #include <asm/desc.h>
 
-
-#undef AC_TIMER_TRACE
-#undef AC_TIMER_STATS
-
 #ifdef AC_TIMER_TRACE
 #define TRC(_x) _x
 #else
@@ -55,22 +52,10 @@ typedef struct ac_timers_st
 {
     spinlock_t lock;
     struct list_head timers;
-    struct ac_timer *prev, *curr;
+    s_time_t    max_diff;
 } __cacheline_aligned ac_timers_t;
 static ac_timers_t ac_timers[NR_CPUS];
 
-#ifdef AC_TIMER_STATS
-#define BUCKETS		1000
-#define MAX_STATS
-typedef struct act_stats_st
-{
-    u32 count;
-    u32 times[2*(BUCKETS)];
-} __cacheline_aligned act_stats_t;
-static act_stats_t act_stats[NR_CPUS];
-
-#endif
-
 /* local prototypes */
 static int  detach_ac_timer(struct ac_timer *timer);
 /*static void ac_timer_debug(unsigned long);*/
@@ -172,14 +157,14 @@ static int detach_ac_timer(struct ac_timer *timer)
  */
 int rem_ac_timer(struct ac_timer *timer)
 {
-    int 		  cpu = smp_processor_id();
-    int           res;
+    int           cpu = smp_processor_id();
+    int           res = 0;
     unsigned long flags;
 
     TRC(printk("ACT  [%02d] remove(): timo=%lld \n", cpu, timer->expires));
-
     spin_lock_irqsave(&ac_timers[cpu].lock, flags);
-    res = detach_ac_timer(timer);	
+    if (timer->timer_list.next)
+        res = detach_ac_timer(timer);   
     spin_unlock_irqrestore(&ac_timers[cpu].lock, flags);
 
     return res;
@@ -207,45 +192,23 @@ int mod_ac_timer(struct ac_timer *timer, s_time_t new_time)
  */
 void do_ac_timer(void)
 {
-    int 			 cpu = smp_processor_id();
-    unsigned long 	 flags;
-    struct ac_timer	 *t;
+    int              cpu = smp_processor_id();
+    unsigned long    flags;
+    struct ac_timer  *t;
+    s_time_t diff, now = NOW();
+    long max;
 
     spin_lock_irqsave(&ac_timers[cpu].lock, flags);
 
  do_timer_again:
 
     TRC(printk("ACT  [%02d] do(): now=%lld\n", cpu, NOW()));
-		
-	/* Sanity: is the timer list empty? */
-    if ( list_empty(&ac_timers[cpu].timers) )
+        
+    /* Sanity: is the timer list empty? */
+    if ( list_empty(&ac_timers[cpu].timers) ) {
         printk("ACT[%02d] do_ac_timer(): timer irq without timer\n", cpu);
-
-#ifdef AC_TIMER_STATS
-    {
-        s32	diff;
-        u32 i;
-        diff = ((s32)(NOW() - t->expires)) / 1000; /* delta in us */
-        if (diff < -BUCKETS)
-            diff = -BUCKETS;
-        else if (diff > BUCKETS)
-            diff = BUCKETS;
-        act_stats[cpu].times[diff+BUCKETS]++;
-        act_stats[cpu].count++;
-
-        if (act_stats[cpu].count >= 5000) {
-            printk("ACT Stats\n");
-			for (i=0; i < 2*BUCKETS; i++) {
-				if (act_stats[cpu].times[i] != 0)
-                    printk("ACT [%02d]: %3dus: %5d\n",
-                           cpu,i-BUCKETS, act_stats[cpu].times[i]);
-                act_stats[cpu].times[i]=0;
-            }
-            act_stats[cpu].count = 0;
-            printk("\n");
-        }
+        return;
     }
-#endif
 
     /* Handle all timeouts in the near future. */
     while ( !list_empty(&ac_timers[cpu].timers) )
@@ -253,12 +216,19 @@ void do_ac_timer(void)
         t = list_entry(ac_timers[cpu].timers.next, 
                        struct ac_timer, timer_list);
         if ( t->expires > (NOW() + TIMER_SLOP) ) break;
+
+        /* do some stats */
+        diff = (now - t->expires);
+        if (diff > 0x7fffffff) diff =  0x7fffffff; /* THIS IS BAD! */
+        max = perfc_valuea(ac_timer_max, cpu);
+        if (diff > max) perfc_seta(ac_timer_max, cpu, diff);
+
         detach_ac_timer(t);
         spin_unlock_irqrestore(&ac_timers[cpu].lock, flags);
         if ( t->function != NULL ) t->function(t->data);
         spin_lock_irqsave(&ac_timers[cpu].lock, flags);
     }
-		
+        
     /* If list not empty then reprogram timer to new head of list */
     if ( !list_empty(&ac_timers[cpu].timers) )
     {
@@ -287,7 +257,7 @@ static void dump_tqueue(struct list_head *queue, char *name)
 {
     struct list_head *list;
     int loop = 0;
-    struct ac_timer	 *t;
+    struct ac_timer  *t;
 
     printk ("QUEUE %s %lx   n: %lx, p: %lx\n", name,  (unsigned long)queue,
             (unsigned long) queue->next, (unsigned long) queue->prev);
@@ -303,18 +273,21 @@ static void dump_tqueue(struct list_head *queue, char *name)
 }
 
 
-static void dump_timerq(u_char key, void *dev_id, struct pt_regs *regs)
+void dump_timerq(u_char key, void *dev_id, struct pt_regs *regs)
 {
     u_long   flags; 
     s_time_t now = NOW();
+    int i;
 
-    printk("Dumping ac_timer queues for cpu 0: NOW=0x%08X%08X\n",
+    printk("Dumping ac_timer queues: NOW=0x%08X%08X\n",
            (u32)(now>>32), (u32)now); 
-	
-    spin_lock_irqsave(&ac_timers[0].lock, flags);
-    dump_tqueue(&ac_timers[0].timers, "ac_time"); 
-    spin_unlock_irqrestore(&ac_timers[0].lock, flags);
-    printk("\n");
+    for (i = 0; i < smp_num_cpus; i++) {
+        printk("CPU[%02d] ", i);
+        spin_lock_irqsave(&ac_timers[i].lock, flags);
+        dump_tqueue(&ac_timers[i].timers, "ac_time"); 
+        spin_unlock_irqrestore(&ac_timers[i].lock, flags);
+        printk("\n");
+    }
     return; 
 }
 
@@ -330,6 +303,4 @@ void __init ac_timer_init(void)
         INIT_LIST_HEAD(&ac_timers[i].timers);
         spin_lock_init(&ac_timers[i].lock);
     }
-
-    add_key_handler('a', dump_timerq, "dump ac_timer queues");
 }
diff --git a/xen/common/keyhandler.c b/xen/common/keyhandler.c
index 8bb4fecab0..1f8a84ea32 100644
--- a/xen/common/keyhandler.c
+++ b/xen/common/keyhandler.c
@@ -2,6 +2,7 @@
 #include <xeno/reboot.h>
 
 extern void perfc_printall (u_char key, void *dev_id, struct pt_regs *regs);
+extern void perfc_reset (u_char key, void *dev_id, struct pt_regs *regs);
 
 #define KEY_MAX 256
 #define STR_MAX  64
@@ -122,6 +123,7 @@ void initialize_keytable()
     add_key_handler('d', dump_registers, "dump registers"); 
     add_key_handler('h', show_handlers, "show this message");
     add_key_handler('p', perfc_printall, "print performance counters"); 
+    add_key_handler('P', perfc_reset,    "reset performance counters"); 
     add_key_handler('q', do_task_queues, "dump task queues + guest state");
     add_key_handler('R', halt_machine, "reboot machine ungracefully"); 
     
diff --git a/xen/common/perfc.c b/xen/common/perfc.c
index 6b7e9f2af3..cc277a914a 100644
--- a/xen/common/perfc.c
+++ b/xen/common/perfc.c
@@ -2,12 +2,19 @@
  * xen performance counters
  */
 
+#include <xeno/lib.h>
+#include <xeno/smp.h>
+#include <xeno/time.h>
 #include <xeno/perfc.h>
 #include <xeno/keyhandler.h> 
 
-#undef  PERFCOUNTER
-#undef  PERFCOUNTER_ARRAY
+/* used for different purposes in perfc.h and here */
+#undef PERFCOUNTER
+#undef PERFCOUNTER_CPU
+#undef PERFCOUNTER_ARRAY
+
 #define PERFCOUNTER( var, name ) "[0]"name"\0",
+#define PERFCOUNTER_CPU( var, name )  "C"name"\0",
 #define PERFCOUNTER_ARRAY( var, name, size )  "["#size"]"name"\0",
 
 char* perfc_name[] = {
@@ -21,63 +28,89 @@ void __perfc_print (unsigned long counter[], int offset)
   int loop;
   int total_size = 0;
   int element_size = 0;
+  int cpus = 0;
   int num = 0;
 
-  for (loop = 0; loop < sizeof(perfc_name) / sizeof(char *); loop++)
-  {
-    num = sscanf (perfc_name[loop], "[%d]", &element_size);
-    total_size += element_size == 0 ? 1 : element_size;
-    if (total_size > offset) break;
-  }
-  if (loop == sizeof(perfc_name) / sizeof(char *))
-  {
-    printf ("error: couldn't find variable\n"); 
-    return;
+  for (loop = 0; loop < sizeof(perfc_name) / sizeof(char *); loop++) {
+      if (perfc_name[loop][0] == 'C') {
+          element_size = NR_CPUS;
+          cpus = 1;
+      } else {
+          num = sscanf (perfc_name[loop], "[%d]", &element_size);
+      }
+
+      total_size += element_size == 0 ? 1 : element_size;
+      if (total_size > offset) break;
   }
-  if (element_size == 0)                                   /* single counter */
-  {
-    printf ("%10ld  0x%08lx  %s\n", counter[0], counter[0],
-	    perfc_name[loop] + 2 + num);
+  if (loop == sizeof(perfc_name) / sizeof(char *)) {
+      printf ("error: couldn't find variable\n"); 
+      return;
   }
-  else                                                  /* show entire array */
-  {
-    for (loop = 0; loop < element_size; loop++)
-    {
-      printf ("%10ld  0x%08lx  %s:%d\n", 
-	      counter[loop], counter[loop], 
-	      perfc_name[loop] + 2 + num, loop);
-    }
+  if (element_size == 0) {                              /* single counter */
+      printf ("%10ld  0x%08lx  %s\n", counter[0], counter[0],
+              perfc_name[loop] + 2 + num);
+  } else if (cpus) {                                    /* counter per CPU  */
+      for (loop = 0; loop < smp_num_cpus; loop++) {
+          printf ("%10ld  0x%08lx  cpu[%02d] %s\n", 
+                  counter[loop], counter[loop], 
+                  loop, perfc_name[loop]);
+      }
+      
+  } else {                                             /* show entire array */
+      for (loop = 0; loop < element_size; loop++) {
+          printf ("%10ld  0x%08lx  %s:%d\n", 
+                  counter[loop], counter[loop], 
+                  perfc_name[loop] + 2 + num, loop);
+      }
   }
   return;
 }
 
 void perfc_printall (u_char key, void *dev_id, struct pt_regs *regs)
 {
-  int loop, idx;
-  int element_size;
-  int num;
-  unsigned long *counters = (unsigned long *)&perfcounters;
+    int loop, idx;
+    int element_size;
+    int cpus=0;
+    int num = 0;
+    s_time_t now = NOW();
+    unsigned long *counters = (unsigned long *)&perfcounters;
+
+    printf ("xen performance counters: now=0x%08X%08X\n",
+            (u32)(now>>32), (u32)now);
+
+    for (loop = 0; loop < sizeof(perfc_name) / sizeof(char *); loop++) {
 
-  printf ("xen performance counters\n");
-  for (loop = 0; loop < sizeof(perfc_name) / sizeof(char *); loop++)
-  {
-    num = sscanf (perfc_name[loop], "[%d]", &element_size);
+        if (perfc_name[loop][0] == 'C') {
+            element_size = NR_CPUS;
+            cpus = 1;
+        } else {
+            num = sscanf (perfc_name[loop], "[%d]", &element_size);
+        }
     
-    for (idx = 0; idx < (element_size ? element_size : 1); idx++)
-    {
-      if (element_size)
-      {
-	printf ("%10ld  0x%08lx  %s:%d\n", 
-		*counters, *counters, perfc_name[loop] + num + 2, idx);
-      }
-      else
-      {
-	printf ("%10ld  0x%08lx  %s\n", 
-		*counters, *counters, perfc_name[loop] + num + 2);
-      }
-      counters++;
+        for (idx = 0; idx < (element_size ? element_size : 1); idx++) {
+            if (cpus) {
+                if (idx < smp_num_cpus)
+                    printf ("%10ld  0x%08lx  cpu[%02d] %s\n", 
+                            *counters, *counters, idx, perfc_name[loop] + 1);
+            } else if (element_size) {
+                printf ("%10ld  0x%08lx  %s:%d\n", 
+                        *counters, *counters, perfc_name[loop] + num + 2, idx);
+            } else {
+                printf ("%10ld  0x%08lx  %s\n", 
+                        *counters, *counters, perfc_name[loop] + num + 2);
+            }
+            counters++;
+        }
     }
-  }
 
-  return;
+    return;
 }
+
+void perfc_reset (u_char key, void *dev_id, struct pt_regs *regs)
+{
+    s_time_t now = NOW();
+    printk ("xen performance counters reset: now=0x%08X%08X\n",
+            (u32)(now>>32), (u32)now);
+    memset (&perfcounters, 0, sizeof(perfcounters));
+}
+
diff --git a/xen/include/xeno/perfc.h b/xen/include/xeno/perfc.h
index 31201eaa6d..4d0164c170 100644
--- a/xen/include/xeno/perfc.h
+++ b/xen/include/xeno/perfc.h
@@ -3,22 +3,31 @@
  */
 
 /* 
- * NOTE: new counters must be defined in xen_perf_defn.h
+ * NOTE: new counters must be defined in perfc_defn.h
  * 
  * PERFCOUNTER (counter, string)              define a new performance counter
+ * PERFCOUNTER_CPU (counter, string, size)    define a counter per CPU
  * PERFCOUNTER_ARRY (counter, string, size)   define an array of counters
  * 
  * unsigned long perfc_value  (counter)        get value of a counter  
+ * unsigned long perfc_valuec (counter)        get value of a per CPU counter
  * unsigned long perfc_valuea (counter, index) get value of an array counter
- * void perfc_incr   (counter)                 increment a counter          
- * void perfc_incra  (counter, index)          increment an array counter   
- * void perfc_add    (counter, value)          add a value to a counter     
- * void perfc_adda   (counter, index, value)   add a value to array counter 
- * void perfc_print  (counter)                 print out the counter
+ * unsigned long perfc_set  (counter, val)     set value of a counter  
+ * unsigned long perfc_setc (counter, val)     set value of a per CPU counter
+ * unsigned long perfc_seta (counter, index, val) set value of an array counter
+ * void perfc_incr  (counter)                  increment a counter          
+ * void perfc_incrc (counter, index)           increment a per CPU counter   
+ * void perfc_incra (counter, index)           increment an array counter   
+ * void perfc_add   (counter, value)           add a value to a counter     
+ * void perfc_addc  (counter, value)           add a value to a per CPU counter
+ * void perfc_adda  (counter, index, value)    add a value to array counter 
+ * void perfc_print (counter)                  print out the counter
  */
 
 #define PERFCOUNTER( var, name ) \
 unsigned long var[1];
+#define PERFCOUNTER_CPU( var, name ) \
+unsigned long var[NR_CPUS];
 #define PERFCOUNTER_ARRAY( var, name, size ) \
 unsigned long var[size];
 
@@ -30,12 +39,18 @@ struct perfcounter_t
 extern struct perfcounter_t perfcounters;
 extern char *perfc_name[];
 
-#define perf_value(x)    perfcounters.x[0]
-#define perf_valuea(x,y) perfcounters.x[y]
-#define perf_incr(x)     perfcounters.x[0]++
-#define perf_incra(x,y)  perfcounters.x[y]++
-#define perf_add(x,y)    perfcounters.x[0]+=(y)
-#define perf_adda(x,y,z) perfcounters.x[y]+=(z)
+#define perfc_value(x)    perfcounters.x[0]
+#define perfc_valuec(x)   perfcounters.x[smp_processor_id()]
+#define perfc_valuea(x,y) perfcounters.x[y]
+#define perfc_set(x,v)    perfcounters.x[0] = v
+#define perfc_setc(x,v)   perfcounters.x[smp_processor_id()] = v
+#define perfc_seta(x,y,v) perfcounters.x[y] = v
+#define perfc_incr(x)     perfcounters.x[0]++
+#define perfc_incrc(x)    perfcounters.x[smp_processor_id()]++
+#define perfc_incra(x,y)  perfcounters.x[y]++
+#define perfc_add(x,y)    perfcounters.x[0]+=(y)
+#define perfc_addc(x,y)   perfcounters.x[smp_processor_id()]+=(y)
+#define perfc_adda(x,y,z) perfcounters.x[y]+=(z)
 
 #define perf_print(x) \
   __perfc_print(perfcounters.x, \
diff --git a/xen/include/xeno/perfc_defn.h b/xen/include/xeno/perfc_defn.h
index 16ab4cd8c9..41dd48f73b 100644
--- a/xen/include/xeno/perfc_defn.h
+++ b/xen/include/xeno/perfc_defn.h
@@ -1,4 +1,10 @@
 
+PERFCOUNTER_CPU( irqs,         "#interrupts" )
+PERFCOUNTER_CPU( irq_time,     "cycles spent in irq handler" )
+
 PERFCOUNTER( blockio_tx, "block io: messages received from tx queue" )
 PERFCOUNTER( blockio_rx, "block io: messages sent on rx queue" )
 
+PERFCOUNTER_CPU( apic_timer,    "apic timer interrupts" )
+PERFCOUNTER_CPU( ac_timer_max,  "ac_timer max error" )
+