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

[Paolo Bonzini]

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 <address@hidden>
> Tested-by: Camille Bégué <address@hidden>
> ---
>  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

>  #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 */