ia64/xen-unstable

changeset 18177:3769051151ae

x86: extend debug key 't' to collect useful clock skew info

By repeating "xm debug-key t; xm dmesg | tail -N" in
dom0 (e.g. with the "watch" command), useful skew info
about the machine can be collected, which will be very
helpful for diagnosing customer problems on misbehaving
machines.

Patch details:
1) Min and max readings from the current sample are useless
so get rid of those but retain the current maxdif (stime skew).
2) Remember max of skew, sum of skews, and a count
so average skew can be displayed.
3) Also record info for cycles (tsc on x86, itc on ia64).

Signed-off-by: Dan Magenheimer <dan.magenheimer@oracle.com>
author Keir Fraser <keir.fraser@citrix.com>
date Mon Jul 28 11:36:39 2008 +0100 (2008-07-28)
parents b47e503f3282
children 7a35ab9dba8a
files xen/common/keyhandler.c
line diff
     1.1 --- a/xen/common/keyhandler.c	Mon Jul 28 11:33:28 2008 +0100
     1.2 +++ b/xen/common/keyhandler.c	Mon Jul 28 11:36:39 2008 +0100
     1.3 @@ -236,6 +236,7 @@ static void dump_domains(unsigned char k
     1.4  
     1.5  static cpumask_t read_clocks_cpumask = CPU_MASK_NONE;
     1.6  static s_time_t read_clocks_time[NR_CPUS];
     1.7 +static u64 read_cycles_time[NR_CPUS];
     1.8  
     1.9  static void read_clocks_slave(void *unused)
    1.10  {
    1.11 @@ -244,14 +245,20 @@ static void read_clocks_slave(void *unus
    1.12      while ( !cpu_isset(cpu, read_clocks_cpumask) )
    1.13          cpu_relax();
    1.14      read_clocks_time[cpu] = NOW();
    1.15 +    read_cycles_time[cpu] = get_cycles();
    1.16      cpu_clear(cpu, read_clocks_cpumask);
    1.17      local_irq_enable();
    1.18  }
    1.19  
    1.20  static void read_clocks(unsigned char key)
    1.21  {
    1.22 -    unsigned int cpu = smp_processor_id(), min_cpu, max_cpu;
    1.23 -    u64 min, max, dif, difus;
    1.24 +    unsigned int cpu = smp_processor_id(), min_stime_cpu, max_stime_cpu;
    1.25 +    unsigned int min_cycles_cpu, max_cycles_cpu;
    1.26 +    u64 min_stime, max_stime, dif_stime;
    1.27 +    u64 min_cycles, max_cycles, dif_cycles;
    1.28 +    static u64 sumdif_stime = 0, maxdif_stime = 0;
    1.29 +    static u64 sumdif_cycles = 0, maxdif_cycles = 0;
    1.30 +    static u32 count = 0;
    1.31      static DEFINE_SPINLOCK(lock);
    1.32  
    1.33      spin_lock(&lock);
    1.34 @@ -261,31 +268,48 @@ static void read_clocks(unsigned char ke
    1.35      local_irq_disable();
    1.36      read_clocks_cpumask = cpu_online_map;
    1.37      read_clocks_time[cpu] = NOW();
    1.38 +    read_cycles_time[cpu] = get_cycles();
    1.39      cpu_clear(cpu, read_clocks_cpumask);
    1.40      local_irq_enable();
    1.41  
    1.42      while ( !cpus_empty(read_clocks_cpumask) )
    1.43          cpu_relax();
    1.44  
    1.45 -    min_cpu = max_cpu = cpu;
    1.46 +    min_stime_cpu = max_stime_cpu = min_cycles_cpu = max_cycles_cpu = cpu;
    1.47      for_each_online_cpu ( cpu )
    1.48      {
    1.49 -        if ( read_clocks_time[cpu] < read_clocks_time[min_cpu] )
    1.50 -            min_cpu = cpu;
    1.51 -        if ( read_clocks_time[cpu] > read_clocks_time[max_cpu] )
    1.52 -            max_cpu = cpu;
    1.53 +        if ( read_clocks_time[cpu] < read_clocks_time[min_stime_cpu] )
    1.54 +            min_stime_cpu = cpu;
    1.55 +        if ( read_clocks_time[cpu] > read_clocks_time[max_stime_cpu] )
    1.56 +            max_stime_cpu = cpu;
    1.57 +        if ( read_cycles_time[cpu] < read_cycles_time[min_cycles_cpu] )
    1.58 +            min_cycles_cpu = cpu;
    1.59 +        if ( read_cycles_time[cpu] > read_cycles_time[max_cycles_cpu] )
    1.60 +            max_cycles_cpu = cpu;
    1.61      }
    1.62  
    1.63 -    min = read_clocks_time[min_cpu];
    1.64 -    max = read_clocks_time[max_cpu];
    1.65 +    min_stime = read_clocks_time[min_stime_cpu];
    1.66 +    max_stime = read_clocks_time[max_stime_cpu];
    1.67 +    min_cycles = read_cycles_time[min_cycles_cpu];
    1.68 +    max_cycles = read_cycles_time[max_cycles_cpu];
    1.69  
    1.70      spin_unlock(&lock);
    1.71  
    1.72 -    dif = difus = max - min;
    1.73 -    do_div(difus, 1000);
    1.74 -    printk("Min = %"PRIu64" ; Max = %"PRIu64" ; Diff = %"PRIu64
    1.75 -           " (%"PRIu64" microseconds)\n",
    1.76 -           min, max, dif, difus);
    1.77 +    dif_stime = max_stime - min_stime;
    1.78 +    if ( dif_stime > maxdif_stime )
    1.79 +        maxdif_stime = dif_stime;
    1.80 +    sumdif_stime += dif_stime;
    1.81 +    dif_cycles = max_cycles - min_cycles;
    1.82 +    if ( dif_cycles > maxdif_cycles )
    1.83 +        maxdif_cycles = dif_cycles;
    1.84 +    sumdif_cycles += dif_cycles;
    1.85 +    count++;
    1.86 +    printk("Synced stime skew: max=%"PRIu64"ns avg=%"PRIu64"ns "
    1.87 +           "samples=%"PRIu32" current=%"PRIu64"ns\n",
    1.88 +           maxdif_stime, sumdif_stime/count, count, dif_stime);
    1.89 +    printk("Synced cycles skew: max=%"PRIu64" avg=%"PRIu64" "
    1.90 +           "samples=%"PRIu32" current=%"PRIu64"\n",
    1.91 +           maxdif_cycles, sumdif_cycles/count, count, dif_cycles);
    1.92  }
    1.93  
    1.94  extern void dump_runq(unsigned char key);