[RFC,V3,5/6] cpu_exec: Print to console if the guest is late

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(-)

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) {
>

----- Mail original -----
> De: "Paolo Bonzini" <pbonzini@redhat.com>
> À: "Sebastian Tanase" <sebastian.tanase@openwide.fr>, qemu-devel@nongnu.org
> Cc: aliguori@amazon.com, afaerber@suse.de, rth@twiddle.net, "peter maydell" <peter.maydell@linaro.org>,
> michael@walle.cc, alex@alex.org.uk, stefanha@redhat.com, lcapitulino@redhat.com, crobinso@redhat.com,
> armbru@redhat.com, wenchaoqemu@gmail.com, quintela@redhat.com, kwolf@redhat.com, mjt@tls.msk.ru, mst@redhat.com
> Envoyé: Lundi 30 Juin 2014 19:11:41
> Objet: Re: [RFC PATCH V3 5/6] cpu_exec: Print to console if the guest is late
> 
> 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
> 

Unifying the 2 structs will certainly make this possible.

Sebastian

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