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

[Sebastian Tanase <sebastian.tanase@openwide.fr>]

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