[Qemu-devel] [RFC PATCH V3 5/6] cpu_exec: Print to console if the guest is late

[Sebastian Tanase]

If the align option is enabled, we print to the user whenever
the guest clock is behind the host clock in order for he/she
to have a hint about the actual performance. The maximum
print interval is 2s and we limit the number of messages to 100.
If desired, this can be changed in cpu-exec.c

Signed-off-by: Sebastian Tanase <address@hidden>
Tested-by: Camille Bégué <address@hidden>
---
 cpu-exec.c | 94 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 90 insertions(+), 4 deletions(-)

diff --git a/cpu-exec.c b/cpu-exec.c
index ac741b7..4a4533d 100644
--- a/cpu-exec.c
+++ b/cpu-exec.c
@@ -24,12 +24,21 @@
 #include "sysemu/qtest.h"
 #include "qemu/timer.h"
 
-/* Structs and function pointers for delaying the host */
+/* Structs and function pointers for delaying the host
+   and printing the clock difference between the guest
+   and the host. */
 typedef struct SyncClocks SyncClocks;
+typedef struct InformDelay InformDelay;
 typedef void (*init_delay_func)(SyncClocks *sc,
+                                int64_t realtime_clock_value,
                                 const CPUState *cpu);
 typedef void (*perform_align_func)(SyncClocks *sc,
                                    const CPUState *cpu);
+typedef void (*init_inform_delay_func)(InformDelay *indl,
+                                       int64_t realtime_clock_value);
+typedef void (*perform_print_func)(InformDelay *indl,
+                                   int64_t diff_clk);
+
 struct SyncClocks {
     int64_t diff_clk;
     int64_t original_instr_counter;
@@ -37,12 +46,22 @@ struct SyncClocks {
     perform_align_func perform_align;
 };
 
+struct InformDelay {
+    int64_t realtime_clock;
+    unsigned int nb_prints;
+    init_inform_delay_func init_inform_delay;
+    perform_print_func perform_print;
+};
+
 #if !defined(CONFIG_USER_ONLY)
 /* Allow the guest to have a max 3ms advance.
  * The difference between the 2 clocks could therefore
  * oscillate around 0.
  */
 #define VM_CLOCK_ADVANCE 3000000
+#define THRESHOLD_REDUCE 1.5
+#define MAX_DELAY_PRINT_RATE 2
+#define MAX_NB_PRINTS 100
 
 static int64_t delay_host(int64_t diff_clk)
 {
@@ -82,10 +101,11 @@ static void align_clocks(SyncClocks *sc, const CPUState 
*cpu)
 }
 
 static void init_delay_params(SyncClocks *sc,
+                              int64_t realtime_clock_value,
                               const CPUState *cpu)
 {
     static int64_t clocks_offset = -1;
-    int64_t realtime_clock_value, virtual_clock_value;
+    int64_t virtual_clock_value;
     if (!icount_align_option) {
         return;
     }
@@ -97,7 +117,6 @@ static void init_delay_params(SyncClocks *sc,
        Therefore we impose that the first time we run the cpu
        the host and virtual clocks should be aligned; we don't alter any of
        the clocks, we just calculate the difference between them. */
-    realtime_clock_value = qemu_clock_get_ns(QEMU_CLOCK_REALTIME);
     virtual_clock_value = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL);
     if (clocks_offset == -1) {
         clocks_offset = realtime_clock_value - virtual_clock_value;
@@ -105,6 +124,47 @@ static void init_delay_params(SyncClocks *sc,
     sc->diff_clk = virtual_clock_value - realtime_clock_value + clocks_offset;
     sc->original_instr_counter = cpu->icount_extra + cpu->icount_decr.u16.low;
 }
+static void print_delay(InformDelay *indl, int64_t diff_clk)
+{
+    static float threshold_delay;
+    static int64_t last_realtime_clock;
+    if (icount_align_option &&
+        (indl->realtime_clock - last_realtime_clock) / 1000000000LL
+        >= MAX_DELAY_PRINT_RATE && indl->nb_prints < MAX_NB_PRINTS) {
+        if (-diff_clk / (float)1000000000LL > threshold_delay) {
+            threshold_delay = (-diff_clk / 1000000000LL) + 1;
+            printf("Warning: The guest is late by %.1f to %.1f seconds\n",
+                   threshold_delay - 1,
+                   threshold_delay);
+            indl->nb_prints++;
+        } else if (-diff_clk / (float)1000000000LL <
+                   (threshold_delay - THRESHOLD_REDUCE)) {
+            threshold_delay = (-diff_clk / 1000000000LL) + 1;
+            printf("Warning: The guest has reduced the delay and is now "
+                   "late by %.1f to %.1f seconds\n",
+                   threshold_delay - 1,
+                   threshold_delay);
+            indl->nb_prints++;
+        }
+        last_realtime_clock = indl->realtime_clock;
+    }
+}
+
+static void init_inform(InformDelay *indl, int64_t realtime_clock_value)
+{
+    if (!icount_align_option) {
+        return;
+    }
+    indl->realtime_clock = realtime_clock_value;
+}
+
+static void compute_value_of_rtc(int64_t *realtime_clock_value)
+{
+    if (!icount_align_option) {
+        return;
+    }
+    *realtime_clock_value = qemu_clock_get_ns(QEMU_CLOCK_REALTIME);
+}
 #else
 /* We don't use the align feature for User emulation
    thus we add empty functions which shall be ignored
@@ -114,9 +174,21 @@ static void align_clocks(SyncClocks *sc, const CPUState 
*cpu)
 }
 
 static void init_delay_params(SyncClocks *sc,
+                              int64_t realtime_clock_value,
                               const CPUState *cpu)
 {
 }
+static void print_delay(InformDelay *indl, int64_t diff_clk)
+{
+}
+
+static void init_inform(InformDelay *indl, int64_t realtime_clock_value)
+{
+}
+
+static void compute_value_of_rtc(int64_t *realtime_clock_value)
+{
+}
 #endif /* CONFIG USER ONLY */
 
 void cpu_loop_exit(CPUState *cpu)
@@ -324,10 +396,16 @@ int cpu_exec(CPUArchState *env)
     uint8_t *tc_ptr;
     uintptr_t next_tb;
     /* Delay algorithm */
+    int64_t realtime_clock_value;
     static SyncClocks sc = {
         .init_delay = init_delay_params,
         .perform_align = align_clocks
     };
+    /* Print delay control */
+    static InformDelay inform_delay = {
+        .init_inform_delay = init_inform,
+        .perform_print = print_delay
+    };
     /* This must be volatile so it is not trashed by longjmp() */
     volatile bool have_tb_lock = false;
 
@@ -384,11 +462,19 @@ int cpu_exec(CPUArchState *env)
 #endif
     cpu->exception_index = -1;
 
+    /* Calculating the realtime is expensive so we do it once here
+       and then pass this value around. */
+    compute_value_of_rtc(&realtime_clock_value);
     /* Calculate difference between guest clock and host clock.
        This delay includes the delay of the last cycle, so
        what we have to do is sleep until it is 0. As for the
        advance/delay we gain here, we try to fix it next time. */
-    sc.init_delay(&sc, cpu);
+    inform_delay.init_inform_delay(&inform_delay, realtime_clock_value);
+    sc.init_delay(&sc, realtime_clock_value, cpu);
+    /* Print every 2s max if the guest is late. We limit the number
+       of printed messages to NB_PRINT_MAX(currently 100) */
+    inform_delay.perform_print(&inform_delay, sc.diff_clk);
+
     /* prepare setjmp context for exception handling */
     for(;;) {
         if (sigsetjmp(cpu->jmp_env, 0) == 0) {
-- 
2.0.0.rc2