[Xen-changelog] [xen master] x86: debugging code for platform timer wrap problem

[patchbot@xxxxxxx]

commit bd9be94eb2280e8e662e75f1e5fea7c12eb2589c
Author:     Jan Beulich <jbeulich@xxxxxxxx>
AuthorDate: Tue Apr 9 13:33:52 2013 +0200
Commit:     Jan Beulich <jbeulich@xxxxxxxx>
CommitDate: Tue Apr 9 13:33:52 2013 +0200

    x86: debugging code for platform timer wrap problem
    
    This is intentionally adding code not well formatted (so it stands out)
    and expected to be reverted as soon as the problem with the timer wraps
    has been spotted.
    
    Signed-off-by: Jan Beulich <jbeulich@xxxxxxxx>
---
 xen/arch/x86/time.c |   58 +++++++++++++++++++++++++++++++++++++++++++--------
 1 files changed, 49 insertions(+), 9 deletions(-)

diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index 56bffdb..b403f47 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -43,6 +43,23 @@
 static char __initdata opt_clocksource[10];
 string_param("clocksource", opt_clocksource);
 
+static int opt_log_time;//temp
+static unsigned int opt_log_time_start;//temp
+static void __init setup_log_time(char *str) {//temp
+ if(!str || !*str) {
+  opt_log_time = -1;
+  opt_log_time_start = -1;
+  return;
+ }
+ opt_log_time = simple_strtoul(str, (const char **)&str, 0);
+ if(*str == ',') {
+  opt_log_time_start = simple_strtoul(str + 1, NULL, 0);
+  if(opt_log_time_start && opt_log_time > 0)
+   opt_log_time = -opt_log_time;
+ }
+}
+custom_param("log_time", setup_log_time);//temp
+
 unsigned long __read_mostly cpu_khz;  /* CPU clock frequency in kHz. */
 DEFINE_SPINLOCK(rtc_lock);
 unsigned long pit0_ticks;
@@ -121,6 +138,7 @@ static inline u64 scale_delta(u64 delta, struct time_scale 
*scale)
 {
     u64 product;
 
+BUG_ON((s64)delta < 0);//temp
     if ( scale->shift < 0 )
         delta >>= -scale->shift;
     else
@@ -527,12 +545,13 @@ static void plt_overflow(void *unused)
 {
     int i;
     u64 count;
+u64 delta;//temp
     s_time_t now, plt_now, plt_wrap;
 
     spin_lock_irq(&platform_timer_lock);
 
     count = plt_src.read_counter();
-    plt_stamp64 += (count - plt_stamp) & plt_mask;
+    plt_stamp64 += delta = (count - plt_stamp) & plt_mask;
     plt_stamp = count;
 
     now = NOW();
@@ -549,11 +568,21 @@ static void plt_overflow(void *unused)
     {
         static bool_t warned_once;
         if ( !test_and_set_bool(warned_once) )
+{//temp
             printk("Platform timer appears to have unexpectedly wrapped "
                    "%u%s times.\n", i, (i == 10) ? " or more" : "");
+ printk("PLT: n=%012"PRIx64" pn=%012"PRIx64" pm=%012"PRIx64" 
pw=%012"PRIx64"\n", now, plt_now, plt_mask, plt_wrap);
+}
     }
 
     spin_unlock_irq(&platform_timer_lock);
+if(opt_log_time) printk("PLT: c=%012"PRIx64" d=%06"PRIx64" s=%012"PRIx64"\n", 
count, delta, plt_stamp64);//temp
+if(opt_log_time > 0) {//temp
+ --opt_log_time;
+} else if (opt_log_time < 0 && !--opt_log_time_start) {
+ opt_log_time = -opt_log_time;
+}
+WARN_ON(platform_timer_stamp && delta < (6 << (plt_src.counter_bits - 
4)));//temp
 
     set_timer(&plt_overflow_timer, NOW() + plt_overflow_period);
 }
@@ -568,6 +597,7 @@ static s_time_t read_platform_stime(void)
     spin_lock(&platform_timer_lock);
     count = plt_stamp64 + ((plt_src.read_counter() - plt_stamp) & plt_mask);
     stime = __read_platform_stime(count);
+BUG_ON((u64)stime >> 55);//temp
     spin_unlock(&platform_timer_lock);
 
     return stime;
@@ -582,9 +612,11 @@ static void platform_time_calibration(void)
     spin_lock_irqsave(&platform_timer_lock, flags);
     count = plt_stamp64 + ((plt_src.read_counter() - plt_stamp) & plt_mask);
     stamp = __read_platform_stime(count);
+BUG_ON((u64)stamp >> 55);//temp
     stime_platform_stamp = stamp;
     platform_timer_stamp = count;
     spin_unlock_irqrestore(&platform_timer_lock, flags);
+if(opt_log_time) printk("PLT: s=%012"PRIx64" c=%012"PRIx64"\n", stamp, 
count);//temp
 }
 
 static void resume_platform_timer(void)
@@ -651,6 +683,7 @@ static void __init init_platform_timer(void)
 
     printk("Platform timer is %s %s\n",
            freq_string(pts->frequency), pts->name);
+if(opt_log_time) printk("PLT: m=%08x s=%d o=%012"PRIx64"\n", 
plt_scale.mul_frac, plt_scale.shift, plt_overflow_period);//temp
 }
 
 u64 stime2tsc(s_time_t stime)
@@ -1034,7 +1067,12 @@ static void local_time_calibration(void)
         t->local_tsc_stamp    = c->local_tsc_stamp;
         t->stime_local_stamp  = c->stime_master_stamp;
         t->stime_master_stamp = c->stime_master_stamp;
+curr_local_stime = c->stime_local_stamp;//temp
         local_irq_enable();
+if(opt_log_time > 0) {//temp
+ printk("UPD%02x: t=%012"PRIx64" l=%012"PRIx64" m=%012"PRIx64"\n",
+        smp_processor_id(), t->local_tsc_stamp, curr_local_stime, 
t->stime_master_stamp);
+}
         update_vcpu_system_time(current);
         goto out;
     }
@@ -1050,14 +1088,14 @@ static void local_time_calibration(void)
     curr_master_stime = c->stime_master_stamp;
     local_irq_enable();
 
-#if 0
-    printk("PRE%d: tsc=%"PRIu64" stime=%"PRIu64" master=%"PRIu64"\n",
+if(opt_log_time > 0) {//temp #if 0
+    printk("PRE%02x: t=%012"PRIx64" l=%012"PRIx64" m=%012"PRIx64"\n",
            smp_processor_id(), prev_tsc, prev_local_stime, prev_master_stime);
-    printk("CUR%d: tsc=%"PRIu64" stime=%"PRIu64" master=%"PRIu64
+    printk("CUR%02x: t=%012"PRIx64" l=%012"PRIx64" m=%012"PRIx64
            " -> %"PRId64"\n",
            smp_processor_id(), curr_tsc, curr_local_stime, curr_master_stime,
            curr_master_stime - curr_local_stime);
-#endif
+}//temp #endif
 
     /* Local time warps forward if it lags behind master time. */
     if ( curr_local_stime < curr_master_stime )
@@ -1124,10 +1162,10 @@ static void local_time_calibration(void)
     if ( error_factor != 0 )
         calibration_mul_frac = mul_frac(calibration_mul_frac, error_factor);
 
-#if 0
-    printk("---%d: %08x %08x %d\n", smp_processor_id(),
-           error_factor, calibration_mul_frac, tsc_shift);
-#endif
+if(opt_log_time > 0) {//temp #if 0
+    printk("NEW%02x: e=%08x m=%08x s=%d\n",
+           smp_processor_id(), error_factor, calibration_mul_frac, tsc_shift);
+}//temp #endif
 
     /* Record new timestamp information, atomically w.r.t. interrupts. */
     local_irq_disable();
@@ -1475,6 +1513,7 @@ int __init init_xen_time(void)
         /* If TSCs are not marked as 'reliable', re-sync during rendezvous. */
         if ( !boot_cpu_has(X86_FEATURE_TSC_RELIABLE) )
             time_calibration_rendezvous_fn = time_calibration_tsc_rendezvous;
+printk("Using %s rendezvous\n", boot_cpu_has(X86_FEATURE_TSC_RELIABLE) ? 
"standard" : "TSC");//temp
     }
 
     open_softirq(TIME_CALIBRATE_SOFTIRQ, local_time_calibration);
@@ -1502,6 +1541,7 @@ void __init early_time_init(void)
     u64 tmp = init_pit_and_calibrate_tsc();
 
     set_time_scale(&this_cpu(cpu_time).tsc_scale, tmp);
+if(opt_log_time) printk("INI: m=%08x s=%d\n", 
this_cpu(cpu_time).tsc_scale.mul_frac, 
this_cpu(cpu_time).tsc_scale.shift);//temp
 
     do_div(tmp, 1000);
     cpu_khz = (unsigned long)tmp;
--
generated by git-patchbot for /home/xen/git/xen.git#master

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