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

[Paolo Bonzini <pbonzini@redhat.com>]

Il 30/06/2014 15:59, Sebastian Tanase ha scritto:
> 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 <sebastian.tanase@openwide.fr>
> Tested-by: Camille Bégué <camille.begue@openwide.fr>
> ---
>  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;
> +};

I think these structs can be unified.

>  #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);

Can this (and compute_clocks_offset) all remain part of init_delay_params?

>      /* 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);

This, too.

Paolo

> +
>      /* prepare setjmp context for exception handling */
>      for(;;) {
>          if (sigsetjmp(cpu->jmp_env, 0) == 0) {
>