RE: RE: [PATCH] record max stime skew (was RE: [PATCH] strictly increasing hvm guest time)

["Dan Magenheimer" <dan.magenheimer@oracle.com>]

[-- Attachment #1: Type: text/plain, Size: 842 bytes --]

> On 4/7/08 16:11, "Dan Magenheimer" <dan.magenheimer@oracle.com> wrote:
> 
> > Oops, I misunderstood that for some reason.
> >
> > Here's a fixed version.  I also now preserve the "Platform timer is"
> > line since that can get flushed out of the dmesg buffer.

OOPS, forgot the patch!  Attached this time.

> > Any idea why the skew can get so bad?
> 
> Not really. We could check in this patch or similar and 
> perhaps collect more
> information.
> 
>  -- Keir

Well one suspicion I had was that very long hpet reads were
getting serialized, but I tried clocksource=acpi and
clocksource=pit and get similar skew range results.
In fact pit shows a max of >17000 vs hpet and acpi closer
to 11000.  (OTOH, I suppose it IS possible that this is
roughly how long it takes to read each of these platform
timers.)

Dan

[-- Attachment #2: maxskew4.patch --]
[-- Type: application/octet-stream, Size: 5842 bytes --]

diff -r 08f77df14cba xen/arch/x86/hvm/vpt.c
--- a/xen/arch/x86/hvm/vpt.c	Wed Jul 02 11:30:37 2008 +0900
+++ b/xen/arch/x86/hvm/vpt.c	Fri Jul 04 09:01:27 2008 -0600
@@ -25,6 +25,8 @@
 #define mode_is(d, name) \
     ((d)->arch.hvm_domain.params[HVM_PARAM_TIMER_MODE] == HVMPTM_##name)
 
+u64 max_guest_time_skew = 0;
+
 void hvm_init_guest_time(struct domain *d)
 {
     struct pl_time *pl = &d->arch.hvm_domain.pl_time;
@@ -38,16 +40,22 @@ u64 hvm_get_guest_time(struct vcpu *v)
 {
     struct pl_time *pl = &v->domain->arch.hvm_domain.pl_time;
     u64 now;
+    int64_t skew;
 
     /* Called from device models shared with PV guests. Be careful. */
     ASSERT(is_hvm_vcpu(v));
 
     spin_lock(&pl->pl_time_lock);
     now = get_s_time() + pl->stime_offset;
-    if ( (int64_t)(now - pl->last_guest_time) >= 0 )
+    if ( ( skew = (int64_t)(now - pl->last_guest_time) ) >= 0 )
         pl->last_guest_time = now;
     else
+    {
+        skew = -skew;
+        if ( skew > max_guest_time_skew )
+            max_guest_time_skew = skew;
         now = pl->last_guest_time;
+    }
     spin_unlock(&pl->pl_time_lock);
 
     return now + v->arch.hvm_vcpu.stime_offset;
diff -r 08f77df14cba xen/arch/x86/time.c
--- a/xen/arch/x86/time.c	Wed Jul 02 11:30:37 2008 +0900
+++ b/xen/arch/x86/time.c	Fri Jul 04 09:01:27 2008 -0600
@@ -69,6 +69,12 @@ static DEFINE_PER_CPU(struct cpu_time, c
 
 /* TSC is invariant on C state entry? */
 static bool_t tsc_invariant;
+
+/* global variables exported to report with debug-key t */
+u64 max_stime_skew = 0;
+u64 stime_skew_zero_cnt = 0,stime_skew_10_cnt = 0, stime_skew_100_cnt = 0;
+u64 stime_skew_1000_cnt = 0,stime_skew_10000_cnt = 0, stime_skew_big_cnt = 0;
+char platform_timer_info[80];
 
 /*
  * We simulate a 32-bit platform timer from the 16-bit PIT ch2 counter.
@@ -560,8 +566,12 @@ static void init_platform_timer(void)
 
     platform_timer_stamp = plt_stamp64;
 
-    printk("Platform timer is %s %s\n",
+    /* preserve for xm debug-key 't' */
+    snprintf(platform_timer_info, sizeof(platform_timer_info),
+           "Platform timer is %s %s",
            freq_string(pts->frequency), pts->name);
+
+    printk("%s\n",platform_timer_info);
 }
 
 void cstate_save_tsc(void)
@@ -808,6 +818,7 @@ static void local_time_calibration(void 
      */
     s_time_t prev_local_stime, curr_local_stime;
     s_time_t prev_master_stime, curr_master_stime;
+    s_time_t curr_stime_skew;
 
     /* TSC timestamps taken during this calibration and prev calibration. */
     u64 prev_tsc, curr_tsc;
@@ -831,6 +842,9 @@ static void local_time_calibration(void 
     /* The overall calibration scale multiplier. */
     u32 calibration_mul_frac;
 
+    /* ignore max skew calculation on first few iterations */
+    static int skip_max_skew_calc = 100;
+
     prev_tsc          = t->local_tsc_stamp;
     prev_local_stime  = t->stime_local_stamp;
     prev_master_stime = t->stime_master_stamp;
@@ -844,6 +858,37 @@ static void local_time_calibration(void 
     curr_local_stime  = get_s_time();
     rdtscll(curr_tsc);
     local_irq_enable();
+
+    /*
+     * Record maximum stime skew from platform timer.  Note that
+     * in the case of a fast local clock, skew reflects the post-adjusted
+     * skew (see below and get_s_time()), not the actual skew.  Also
+     * note that some processors may skew positive and others negative
+     * relative to platform timer so skew between ANY pair of processors may be
+     * as much as 2x recorded max
+     */
+    if ( skip_max_skew_calc > 0)
+        skip_max_skew_calc--;  /* allow calibration to converge */
+    else
+    {
+        curr_stime_skew = curr_master_stime - curr_local_stime;
+        if ( (s64) curr_stime_skew < 0 )
+            curr_stime_skew = - curr_stime_skew;
+        if ( curr_stime_skew > max_stime_skew )
+            max_stime_skew = curr_stime_skew;
+        if ( !curr_stime_skew )
+            stime_skew_zero_cnt++;
+        else if ( curr_stime_skew < 10 )
+            stime_skew_10_cnt++;
+        else if ( curr_stime_skew < 100 )
+            stime_skew_100_cnt++;
+        else if ( curr_stime_skew < 1000 )
+            stime_skew_1000_cnt++;
+        else if ( curr_stime_skew < 10000 )
+	    stime_skew_10000_cnt++;
+        else
+            stime_skew_big_cnt++;
+    }
 
 #if 0
     printk("PRE%d: tsc=%"PRIu64" stime=%"PRIu64" master=%"PRIu64"\n",
diff -r 08f77df14cba xen/common/keyhandler.c
--- a/xen/common/keyhandler.c	Wed Jul 02 11:30:37 2008 +0900
+++ b/xen/common/keyhandler.c	Fri Jul 04 09:01:27 2008 -0600
@@ -251,6 +251,10 @@ static void read_clocks(unsigned char ke
     unsigned int cpu = smp_processor_id(), min_cpu, max_cpu;
     u64 min, max, dif, difus;
     static DEFINE_SPINLOCK(lock);
+    extern u64 max_stime_skew, max_guest_time_skew;
+    extern u64 stime_skew_zero_cnt, stime_skew_10_cnt, stime_skew_100_cnt;
+    extern u64 stime_skew_1000_cnt, stime_skew_10000_cnt, stime_skew_big_cnt;
+    extern char platform_timer_info[80];
 
     spin_lock(&lock);
 
@@ -281,9 +285,18 @@ static void read_clocks(unsigned char ke
 
     dif = difus = max - min;
     do_div(difus, 1000);
+    printk("%s\n",platform_timer_info);
     printk("Min = %"PRIu64" ; Max = %"PRIu64" ; Diff = %"PRIu64
            " (%"PRIu64" microseconds)\n",
            min, max, dif, difus);
+    printk("Max stime skew = %"PRIu64"ns; Max guest stoppage = %"PRIu64"ns\n",
+           max_stime_skew, max_guest_time_skew);
+    printk("stime skew counts: 0=%"PRIu64"; ",stime_skew_zero_cnt);
+    printk("-10=%"PRIu64"; ",stime_skew_10_cnt);
+    printk("-100=%"PRIu64"; ",stime_skew_100_cnt);
+    printk("-1000=%"PRIu64"; ",stime_skew_1000_cnt);
+    printk("-10000=%"PRIu64"; ",stime_skew_10000_cnt);
+    printk(">10000=%"PRIu64"\n",stime_skew_big_cnt);
 }
 
 extern void dump_runq(unsigned char key);

[-- Attachment #3: Type: text/plain, Size: 138 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel