PV timer issues in FreeBSD

["Roger Pau Monné" <roger.pau@citrix.com>]

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

Hello,

While trying to get PV timers on FreeBSD to work, we found that when the
system is under stress sometimes FreeBSD would stop receiving timer
interrupts on certain vCPUs. I've added some trace points to Xen in
order to see what was happening with this timers and got the following
trace. I'm also attaching the crappy changes I've did to Xen in order to
add the trace points, maybe I didn't put the trace points in the right
position and that's why I'm seeing this:

 169.097952305 |..x.... d32768v3 d32768 fire timer vCPU3: 1204944804808
 169.097966813 |..x.... d32768v3 d32768 set timer vCPU3: 1204946614221
 169.097977454 |..x.... d32768v3 d32768 set timer vCPU3: 1204963746273
 169.103410517 |..x.... d32768v3 d32768 set timer vCPU3: 1204952682637
 169.103429902 |..x.... d32768v3 d32768 set timer vCPU3: 1205000356797
 169.124982369 |..x.... d32768v3 d32768 set timer vCPU3: 1204976302984
 169.124988972 |..x.... d32768v3 d32768 set timer vCPU3: 1205000356855
 169.128470252 |..x.... d32768v3 d32768 set timer vCPU3: 1204976300693
 169.128639545 |..x.... d32768v3 d32768 set timer vCPU3: 1205000356796
 169.136240633 |..x.... d32768v3 d32768 set timer vCPU3: 1204984176928
 169.136246955 |..x.... d32768v3 d32768 set timer vCPU3: 1205000357030
 169.139729248 |..x.... d32768v3 d32768 set timer vCPU3: 1204992115770
 169.139892831 |..x.... d32768v3 d32768 set timer vCPU3: 1205032863201
 169.151133497 |..x.... d32768v3 d32768 set timer vCPU3: 1204999923870
 169.151137341 |..x.... d32768v3 d32768 set timer vCPU3: 1205032863121
 169.352765068 |..x.... d32768v3 d32768 set timer vCPU3: 1205204647080
 169.352769008 |..x.... d32768v3 d32768 set timer vCPU3: 1205633794418
 176.818699597 |..x.... d32768v3 d32768 set timer vCPU3: 1212676613211
 176.818702670 |..x.... d32768v3 d32768 set timer vCPU3: 1213055669298
 318.489693649 |..x.... d32768v3 d32768 set timer vCPU3: 1354464489030 <
 318.489698326 |..x.... d32768v3 d32768 set timer vCPU3: 1354766606923
 318.491853105 |..x.... d32768v3 d32768 set timer vCPU3: 1354464489183
 318.491857363 |..x.... d32768v3 d32768 set timer vCPU3: 1354766606862
 318.494243541 |..x.... d32768v3 d32768 set timer vCPU3: 1354466611397
 318.494253173 |..x.... d32768v3 d32768 set timer vCPU3: 1354766607167
 318.497005208 |..x.... d32768v3 d32768 set timer vCPU3: 1354472363654
 318.497009517 |..x.... d32768v3 d32768 set timer vCPU3: 1354766606858

As it can be seen above, the vCPU was expecting a timer to fire at
1213055669298, but as far as I can tell the timer never reached the
guest, neither Xen called execute_timer to fire the timer.

Then in order to reset the timer I've started some other task that
probably sends an IPI to the stuck processor and it tries to set the
timer again (this time successfully).

Is there any reason that could prevent the timer from being fired?

Thanks, Roger.

[-- Attachment #2: trace_timer.patch --]
[-- Type: text/plain, Size: 3515 bytes --]

diff --git a/xen/common/domain.c b/xen/common/domain.c
index 64ee29d..ac59452 100644
--- a/xen/common/domain.c
+++ b/xen/common/domain.c
@@ -937,18 +937,27 @@ long do_vcpu_op(int cmd, int vcpuid, XEN_GUEST_HANDLE_PARAM(void) arg)
     {
         struct vcpu_set_singleshot_timer set;
 
-        if ( v != current )
+        if ( v != current ) {
+            TRACE_1D(TRC_PV_TIMER_FAIL, 1);
             return -EINVAL;
+        }
 
-        if ( copy_from_guest(&set, arg, 1) )
+        if ( copy_from_guest(&set, arg, 1) ) {
+            TRACE_1D(TRC_PV_TIMER_FAIL, 2);
             return -EFAULT;
+        }
 
         if ( (set.flags & VCPU_SSHOTTMR_future) &&
-             (set.timeout_abs_ns < NOW()) )
+             (set.timeout_abs_ns < NOW()) ) {
+            TRACE_1D(TRC_PV_TIMER_FAIL, 3);
             return -ETIME;
+        }
 
         migrate_timer(&v->singleshot_timer, smp_processor_id());
+        v->singleshot_timer.debug = 1;
         set_timer(&v->singleshot_timer, set.timeout_abs_ns);
+        TRACE_2D(TRC_PV_SET_TIMER, (uint32_t)set.timeout_abs_ns,
+            (uint32_t)(set.timeout_abs_ns >> 32));
 
         break;
     }
@@ -958,6 +967,8 @@ long do_vcpu_op(int cmd, int vcpuid, XEN_GUEST_HANDLE_PARAM(void) arg)
             return -EINVAL;
 
         stop_timer(&v->singleshot_timer);
+        TRACE_2D(TRC_PV_STOP_TIMER, (uint32_t)v->singleshot_timer.expires,
+            (uint32_t)(v->singleshot_timer.expires >> 32));
 
         break;
 
diff --git a/xen/common/timer.c b/xen/common/timer.c
index 9ed74e9..61e4383 100644
--- a/xen/common/timer.c
+++ b/xen/common/timer.c
@@ -21,6 +21,7 @@
 #include <xen/cpu.h>
 #include <xen/rcupdate.h>
 #include <xen/symbols.h>
+#include <xen/trace.h>
 #include <asm/system.h>
 #include <asm/desc.h>
 #include <asm/atomic.h>
@@ -421,6 +422,9 @@ static void execute_timer(struct timers *ts, struct timer *t)
     list_add(&t->inactive, &ts->inactive);
 
     ts->running = t;
+    if (t->debug)
+        TRACE_2D(TRC_PV_FIRE_TIMER, (uint32_t)t->expires,
+                (uint32_t)(t->expires >> 32));
     spin_unlock_irq(&ts->lock);
     (*fn)(data);
     spin_lock_irq(&ts->lock);
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index e2f60a6..4571d74 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -122,6 +122,7 @@
 
 #define TRC_PV_ENTRY   0x00201000 /* Hypervisor entry points for PV guests. */
 #define TRC_PV_SUBCALL 0x00202000 /* Sub-call in a multicall hypercall */
+#define TRC_PV_TIMER   0x00208000 /* PV timer */
 
 #define TRC_PV_HYPERCALL             (TRC_PV_ENTRY +  1)
 #define TRC_PV_TRAP                  (TRC_PV_ENTRY +  3)
@@ -136,6 +137,10 @@
 #define TRC_PV_PTWR_EMULATION_PAE    (TRC_PV_ENTRY + 12)
 #define TRC_PV_HYPERCALL_V2          (TRC_PV_ENTRY + 13)
 #define TRC_PV_HYPERCALL_SUBCALL     (TRC_PV_SUBCALL + 14)
+#define TRC_PV_SET_TIMER             (TRC_PV_TIMER + 15)
+#define TRC_PV_FIRE_TIMER            (TRC_PV_TIMER + 16)
+#define TRC_PV_TIMER_FAIL            (TRC_PV_TIMER + 17)
+#define TRC_PV_STOP_TIMER            (TRC_PV_TIMER + 18)
 
 /*
  * TRC_PV_HYPERCALL_V2 format
diff --git a/xen/include/xen/timer.h b/xen/include/xen/timer.h
index 9531800..b69ae20 100644
--- a/xen/include/xen/timer.h
+++ b/xen/include/xen/timer.h
@@ -43,6 +43,7 @@ struct timer {
 #define TIMER_STATUS_in_heap  3 /* In use; on timer heap.           */
 #define TIMER_STATUS_in_list  4 /* In use; on overflow linked list. */
     uint8_t status;
+    uint8_t debug;
 };
 
 /*

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

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