Re: [Qemu-devel] [RFC PATCH V2 5/5] 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,
> "camille begue" <camille.begue@openwide.fr>, "pierre lemagourou" <pierre.lemagourou@openwide.fr>, "jeremy rosen"
> <jeremy.rosen@openwide.fr>
> Envoyé: Vendredi 13 Juin 2014 12:29:36
> Objet: Re: [RFC PATCH V2 5/5] cpu_exec: Print to console if the guest is late
> 
> Il 13/06/2014 11:40, 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 so as not to spam the console.
> >
> > Signed-off-by: Sebastian Tanase <sebastian.tanase@openwide.fr>
> > Tested-by: Camille Bégué <camille.begue@openwide.fr>
> > ---
> >  cpu-exec.c | 32 +++++++++++++++++++++++++++++++-
> >  1 file changed, 31 insertions(+), 1 deletion(-)
> >
> > diff --git a/cpu-exec.c b/cpu-exec.c
> > index 5a3bc5e..a386592 100644
> > --- a/cpu-exec.c
> > +++ b/cpu-exec.c
> > @@ -216,6 +216,8 @@ static void
> > cpu_handle_debug_exception(CPUArchState *env)
> >   * oscillate around 0.
> >   */
> >  #define VM_CLOCK_ADVANCE 3000000
> > +#define THRESHOLD_REDUCE 1.5
> > +#define MAX_DELAY_PRINT_RATE 2
> >
> >  static int64_t delay_host(int64_t diff_clk)
> >  {
> > @@ -257,6 +259,29 @@ static int64_t align_clocks(int64_t diff_clk,
> > int64_t *oic, CPUState *cpu)
> >      return diff_clk;
> >  }
> >
> > +static void print_delay(int64_t diff_clk, int64_t realtime_clock)
> > +{
> > +    static float threshold_delay;
> > +    static int64_t last_realtime_clock;
> > +
> > +    if ((realtime_clock - last_realtime_clock) / 1000000000LL
> > +        >= MAX_DELAY_PRINT_RATE) {
> > +        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);
> > +        } 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);
> > +        }
> > +        last_realtime_clock = realtime_clock;
> > +    }
> > +}
> 
> Perhaps stop printing the message after the first 50-100 times?
> 
> Paolo
> 

Thank you very much for your feedback.
Maybe adding a monitor command (info drift) would be better ? Then
the user would not be spammed by printfs.

Sebastian Tanase

> >  #endif /* CONFIG USER ONLY */
> >
> >  /* main execution loop */
> > @@ -278,6 +303,8 @@ int cpu_exec(CPUArchState *env)
> >      uint8_t *tc_ptr;
> >      uintptr_t next_tb;
> >  #if !(defined(CONFIG_USER_ONLY))
> > +    /* Print delay control */
> > +    static int64_t realtime_clock;
> >      /* Delay algorithm */
> >      int64_t diff_clk, original_instr_counter;
> >  #endif
> > @@ -342,9 +369,12 @@ int cpu_exec(CPUArchState *env)
> >             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.
> >             */
> > +        realtime_clock = qemu_clock_get_ns(QEMU_CLOCK_REALTIME);
> >          diff_clk = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) -
> > -                   qemu_clock_get_ns(QEMU_CLOCK_REALTIME) +
> > clocks_offset;
> > +                   realtime_clock + clocks_offset;
> >          original_instr_counter = cpu->icount_extra +
> >          cpu->icount_decr.u16.low;
> > +        /* Print (every 2s max) if the guest is behind the host */
> > +        print_delay(diff_clk, realtime_clock);
> >      }
> >  #endif
> >      /* prepare setjmp context for exception handling */
> >
> 
>