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: 844 bytes --]

> > Attached is the patch.  Interestingly, on my single-socket
> > two-core recent-vintage Intel processor, this patch reports
> > a max skew of >13 usec, much higher than the values I'm
> > seeing from "xm debug-key t".  I wonder if this is due to
> > a mistake in my patch (though I don't see it) or if the
> > various stime error corrections are not converging as
> > expected, resulting in a broader stime skew between
> > processors than expected?
> 
> Perhaps this relatively large skew happens at start of day, before the
> periodic calibration has 'locked on'?

Indeed you are correct.  This updated patch now reports zero skew
as expected.

IMHO, it would be nice to put this patch into the tree as it
will be good for helping to diagnose time skew problems
such as the one just reported on the list.

Thanks,
Dan

[-- Attachment #2: maxskew2.patch --]
[-- Type: application/octet-stream, Size: 3838 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	Thu Jul 03 10:10:03 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	Thu Jul 03 10:10:03 2008 -0600
@@ -69,6 +69,9 @@ static DEFINE_PER_CPU(struct cpu_time, c
 
 /* TSC is invariant on C state entry? */
 static bool_t tsc_invariant;
+
+/* record maximum skew to report with debug-key t */
+u64 max_stime_skew = 0;
 
 /*
  * We simulate a 32-bit platform timer from the 16-bit PIT ch2 counter.
@@ -831,6 +834,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 = 1000;
+
     prev_tsc          = t->local_tsc_stamp;
     prev_local_stime  = t->stime_local_stamp;
     prev_master_stime = t->stime_master_stamp;
@@ -844,6 +850,25 @@ static void local_time_calibration(void 
     curr_local_stime  = get_s_time();
     rdtscll(curr_tsc);
     local_irq_enable();
+
+    /*
+     * Record maximum stime skew from master processor.  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 master so skew between ANY pair of processors may be
+     * as much as 2x recorded max
+     */
+    if ( skip_max_skew_calc )
+        skip_max_skew_calc--;
+    else if ( smp_processor_id() )
+    {
+        s64 curr_stime_skew = curr_master_stime - curr_local_stime;
+        if ( curr_stime_skew < 0 )
+            curr_stime_skew = - curr_stime_skew;
+        if ( curr_stime_skew > max_stime_skew )
+            max_stime_skew = curr_stime_skew;
+    }
 
 #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	Thu Jul 03 10:10:03 2008 -0600
@@ -251,6 +251,7 @@ 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;
 
     spin_lock(&lock);
 
@@ -284,6 +285,8 @@ static void read_clocks(unsigned char ke
     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);
 }
 
 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