[Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Hi,

This is the latest iteration of fixes for problems introduced by
MTTCG. Aside from the usual slew of addressing review comments and
applying tags I've also pulled in Yongbok Kim's MIPS patch (to replace
mine) and Paolo's VMEXIT fix for the problem reported by Alexander
Boettcher.

Unless anyone shouts I'll wrap these up into a pull request for Peter
tomorrow.

I'm hoping the relative quite on the list is because other
architectures have so far been un-affected by the changes ;-)

However it is a timely reminder with the 2.9 rc0 coming up that now is
the time for target maintainers to check everything is still working
as expected.

The next thing on my list it to look at the icount problems and review
Paolo's fixes for it. However those fixes should go in a separate
series and I assume via Paolo's tree.

Thanks,

Alex.

Alex Bennée (9):
  vl/cpus: be smarter with icount and MTTCG
  target/i386/cpu.h: declare TCG_GUEST_DEFAULT_MO
  cpus.c: add additional error_report when !TARGET_SUPPORT_MTTCG
  sparc/sparc64: grab BQL before calling cpu_check_irqs
  s390x/misc_helper.c: wrap IO instructions in BQL
  target/xtensa: hold BQL for interrupt processing
  translate-all: exit cpu_restore_state early if translating
  target/arm/helper: make it clear the EC field is also in hex
  hw/intc/arm_gic: modernise the DPRINTF

Paolo Bonzini (1):
  target-i386: defer VMEXIT to do_interrupt

Yongbok Kim (1):
  target/mips: hold BQL for timer interrupts

 cpus.c                      | 11 +++++++----
 hw/intc/arm_gic.c           | 13 +++++++++----
 hw/sparc/sun4m.c            |  3 +++
 hw/sparc64/sparc64.c        |  3 +++
 target/arm/helper.c         |  2 +-
 target/i386/cpu.h           |  5 +++++
 target/i386/seg_helper.c    | 20 +++++++++++---------
 target/i386/svm_helper.c    | 22 +++++++++++++---------
 target/mips/op_helper.c     | 21 ++++++++++++++++++---
 target/s390x/misc_helper.c  | 21 +++++++++++++++++++++
 target/sparc/int64_helper.c |  3 +++
 target/sparc/win_helper.c   | 13 +++++++++++++
 target/xtensa/helper.c      |  1 +
 target/xtensa/op_helper.c   |  7 +++++++
 translate-all.c             | 13 +++++++++++++
 vl.c                        |  7 ++-----
 16 files changed, 130 insertions(+), 35 deletions(-)

-- 
2.11.0

[Qemu-devel] [PATCH v3 01/11] vl/cpus: be smarter with icount and MTTCG

[Alex Bennée]

The sense of the test was inverted. Make it simple, if icount is
enabled then we disabled MTTCG by default. If the user tries to force
MTTCG upon us then we tell them "no".

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Richard Henderson <rth@twiddle.net>
---
 cpus.c | 7 +++----
 vl.c   | 7 ++-----
 2 files changed, 5 insertions(+), 9 deletions(-)

diff --git a/cpus.c b/cpus.c
index c857ad2957..6a817fec13 100644
--- a/cpus.c
+++ b/cpus.c
@@ -181,10 +181,7 @@ static bool check_tcg_memory_orders_compatible(void)
 
 static bool default_mttcg_enabled(void)
 {
-    QemuOpts *icount_opts = qemu_find_opts_singleton("icount");
-    const char *rr = qemu_opt_get(icount_opts, "rr");
-
-    if (rr || TCG_OVERSIZED_GUEST) {
+    if (use_icount || TCG_OVERSIZED_GUEST) {
         return false;
     } else {
 #ifdef TARGET_SUPPORTS_MTTCG
@@ -202,6 +199,8 @@ void qemu_tcg_configure(QemuOpts *opts, Error **errp)
         if (strcmp(t, "multi") == 0) {
             if (TCG_OVERSIZED_GUEST) {
                 error_setg(errp, "No MTTCG when guest word size > hosts");
+            } else if (use_icount) {
+                error_setg(errp, "No MTTCG when icount is enabled");
             } else {
                 if (!check_tcg_memory_orders_compatible()) {
                     error_report("Guest expects a stronger memory ordering "
diff --git a/vl.c b/vl.c
index 71b75ef8a0..7aea62d0a5 100644
--- a/vl.c
+++ b/vl.c
@@ -4026,8 +4026,6 @@ int main(int argc, char **argv, char **envp)
 
     replay_configure(icount_opts);
 
-    qemu_tcg_configure(accel_opts, &error_fatal);
-
     machine_class = select_machine();
 
     set_memory_options(&ram_slots, &maxram_size, machine_class);
@@ -4394,14 +4392,13 @@ int main(int argc, char **argv, char **envp)
         if (!tcg_enabled()) {
             error_report("-icount is not allowed with hardware virtualization");
             exit(1);
-        } else if (qemu_tcg_mttcg_enabled()) {
-            error_report("-icount does not currently work with MTTCG");
-            exit(1);
         }
         configure_icount(icount_opts, &error_abort);
         qemu_opts_del(icount_opts);
     }
 
+    qemu_tcg_configure(accel_opts, &error_fatal);
+
     if (default_net) {
         QemuOptsList *net = qemu_find_opts("net");
         qemu_opts_set(net, NULL, "type", "nic", &error_abort);
-- 
2.11.0

[Qemu-devel] [PATCH v3 02/11] target/i386/cpu.h: declare TCG_GUEST_DEFAULT_MO

[Alex Bennée]

This suppresses the incorrect warning when forcing MTTCG for x86
guests on x86 hosts. A future patch will still warn when
TARGET_SUPPORT_MTTCG hasn't been defined for the guest (which is still
pending for x86).

Reported-by: Paolo Bonzini <pbonzini@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Richard Henderson <rth@twiddle.net>
Reviewed-by: Eduardo Habkost <ehabkost@redhat.com>
Acked-by: Eduardo Habkost <ehabkost@redhat.com>
---
 target/i386/cpu.h | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/target/i386/cpu.h b/target/i386/cpu.h
index ac2ad6d443..fb09aee7f8 100644
--- a/target/i386/cpu.h
+++ b/target/i386/cpu.h
@@ -30,6 +30,9 @@
 #define TARGET_LONG_BITS 32
 #endif
 
+/* The x86 has a strong memory model with some store-after-load re-ordering */
+#define TCG_GUEST_DEFAULT_MO      (TCG_MO_ALL & ~TCG_MO_ST_LD)
+
 /* Maximum instruction code size */
 #define TARGET_MAX_INSN_SIZE 16
 
-- 
2.11.0

[Qemu-devel] [PATCH v3 03/11] cpus.c: add additional error_report when !TARGET_SUPPORT_MTTCG

[Alex Bennée]

While we may fail the memory ordering check later that can be
confusing. So in cases where TARGET_SUPPORT_MTTCG has yet to be
defined we should say so specifically.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Richard Henderson <rth@twiddle.net>
---
 cpus.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/cpus.c b/cpus.c
index 6a817fec13..69e21858b8 100644
--- a/cpus.c
+++ b/cpus.c
@@ -202,6 +202,10 @@ void qemu_tcg_configure(QemuOpts *opts, Error **errp)
             } else if (use_icount) {
                 error_setg(errp, "No MTTCG when icount is enabled");
             } else {
+#ifndef TARGET_SUPPORT_MTTCG
+                error_report("Guest not yet converted to MTTCG - "
+                             "you may get unexpected results");
+#endif
                 if (!check_tcg_memory_orders_compatible()) {
                     error_report("Guest expects a stronger memory ordering "
                                  "than the host provides");
-- 
2.11.0

Re: [Qemu-devel] [PATCH v3 03/11] cpus.c: add additional error_report when !TARGET_SUPPORT_MTTCG

[Philippe Mathieu-Daudé]

On 03/07/2017 12:50 PM, Alex Bennée wrote:
> While we may fail the memory ordering check later that can be
> confusing. So in cases where TARGET_SUPPORT_MTTCG has yet to be
> defined we should say so specifically.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Reviewed-by: Richard Henderson <rth@twiddle.net>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  cpus.c | 4 ++++
>  1 file changed, 4 insertions(+)
>
> diff --git a/cpus.c b/cpus.c
> index 6a817fec13..69e21858b8 100644
> --- a/cpus.c
> +++ b/cpus.c
> @@ -202,6 +202,10 @@ void qemu_tcg_configure(QemuOpts *opts, Error **errp)
>              } else if (use_icount) {
>                  error_setg(errp, "No MTTCG when icount is enabled");
>              } else {
> +#ifndef TARGET_SUPPORT_MTTCG
> +                error_report("Guest not yet converted to MTTCG - "
> +                             "you may get unexpected results");
> +#endif
>                  if (!check_tcg_memory_orders_compatible()) {
>                      error_report("Guest expects a stronger memory ordering "
>                                   "than the host provides");
>

[Qemu-devel] [PATCH v3 04/11] sparc/sparc64: grab BQL before calling cpu_check_irqs

[Alex Bennée]

IRQ modification is part of device emulation and should be done while
the BQL is held to prevent races when MTTCG is enabled. This adds
assertions in the hw emulation layer and wraps the calls from helpers
in the BQL.

Reported-by: Mark Cave-Ayland <mark.cave-ayland@ilande.co.uk>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---
v3
  - move BQL from cpu_put_psr to helper_wpsr
  - comment cpu_put_psr is under BQL
---
 hw/sparc/sun4m.c            |  3 +++
 hw/sparc64/sparc64.c        |  3 +++
 target/sparc/int64_helper.c |  3 +++
 target/sparc/win_helper.c   | 13 +++++++++++++
 4 files changed, 22 insertions(+)

diff --git a/hw/sparc/sun4m.c b/hw/sparc/sun4m.c
index 61416a6426..873cd7df9a 100644
--- a/hw/sparc/sun4m.c
+++ b/hw/sparc/sun4m.c
@@ -142,6 +142,9 @@ void cpu_check_irqs(CPUSPARCState *env)
 {
     CPUState *cs;
 
+    /* We should be holding the BQL before we mess with IRQs */
+    g_assert(qemu_mutex_iothread_locked());
+
     if (env->pil_in && (env->interrupt_index == 0 ||
                         (env->interrupt_index & ~15) == TT_EXTINT)) {
         unsigned int i;
diff --git a/hw/sparc64/sparc64.c b/hw/sparc64/sparc64.c
index b3d219c769..4e4fdab065 100644
--- a/hw/sparc64/sparc64.c
+++ b/hw/sparc64/sparc64.c
@@ -55,6 +55,9 @@ void cpu_check_irqs(CPUSPARCState *env)
     uint32_t pil = env->pil_in |
                   (env->softint & ~(SOFTINT_TIMER | SOFTINT_STIMER));
 
+    /* We should be holding the BQL before we mess with IRQs */
+    g_assert(qemu_mutex_iothread_locked());
+
     /* TT_IVEC has a higher priority (16) than TT_EXTINT (31..17) */
     if (env->ivec_status & 0x20) {
         return;
diff --git a/target/sparc/int64_helper.c b/target/sparc/int64_helper.c
index 605747c93c..f942973c22 100644
--- a/target/sparc/int64_helper.c
+++ b/target/sparc/int64_helper.c
@@ -18,6 +18,7 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/main-loop.h"
 #include "cpu.h"
 #include "exec/helper-proto.h"
 #include "exec/log.h"
@@ -208,7 +209,9 @@ static bool do_modify_softint(CPUSPARCState *env, uint32_t value)
         env->softint = value;
 #if !defined(CONFIG_USER_ONLY)
         if (cpu_interrupts_enabled(env)) {
+            qemu_mutex_lock_iothread();
             cpu_check_irqs(env);
+            qemu_mutex_unlock_iothread();
         }
 #endif
         return true;
diff --git a/target/sparc/win_helper.c b/target/sparc/win_helper.c
index 71b3dd37e8..154279ecda 100644
--- a/target/sparc/win_helper.c
+++ b/target/sparc/win_helper.c
@@ -18,6 +18,7 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/main-loop.h"
 #include "cpu.h"
 #include "exec/exec-all.h"
 #include "exec/helper-proto.h"
@@ -82,6 +83,7 @@ void cpu_put_psr_raw(CPUSPARCState *env, target_ulong val)
 #endif
 }
 
+/* Called with BQL held */
 void cpu_put_psr(CPUSPARCState *env, target_ulong val)
 {
     cpu_put_psr_raw(env, val);
@@ -153,7 +155,10 @@ void helper_wrpsr(CPUSPARCState *env, target_ulong new_psr)
     if ((new_psr & PSR_CWP) >= env->nwindows) {
         cpu_raise_exception_ra(env, TT_ILL_INSN, GETPC());
     } else {
+        /* cpu_put_psr may trigger interrupts, hence BQL */
+        qemu_mutex_lock_iothread();
         cpu_put_psr(env, new_psr);
+        qemu_mutex_unlock_iothread();
     }
 }
 
@@ -368,7 +373,9 @@ void helper_wrpstate(CPUSPARCState *env, target_ulong new_state)
 
 #if !defined(CONFIG_USER_ONLY)
     if (cpu_interrupts_enabled(env)) {
+        qemu_mutex_lock_iothread();
         cpu_check_irqs(env);
+        qemu_mutex_unlock_iothread();
     }
 #endif
 }
@@ -381,7 +388,9 @@ void helper_wrpil(CPUSPARCState *env, target_ulong new_pil)
     env->psrpil = new_pil;
 
     if (cpu_interrupts_enabled(env)) {
+        qemu_mutex_lock_iothread();
         cpu_check_irqs(env);
+        qemu_mutex_unlock_iothread();
     }
 #endif
 }
@@ -408,7 +417,9 @@ void helper_done(CPUSPARCState *env)
 
 #if !defined(CONFIG_USER_ONLY)
     if (cpu_interrupts_enabled(env)) {
+        qemu_mutex_lock_iothread();
         cpu_check_irqs(env);
+        qemu_mutex_unlock_iothread();
     }
 #endif
 }
@@ -435,7 +446,9 @@ void helper_retry(CPUSPARCState *env)
 
 #if !defined(CONFIG_USER_ONLY)
     if (cpu_interrupts_enabled(env)) {
+        qemu_mutex_lock_iothread();
         cpu_check_irqs(env);
+        qemu_mutex_unlock_iothread();
     }
 #endif
 }
-- 
2.11.0

[Qemu-devel] [PATCH v3 05/11] s390x/misc_helper.c: wrap IO instructions in BQL

[Alex Bennée]

Helpers that can trigger IO events (including interrupts) need to be
protected by the BQL. I've updated all the helpers that call into an
ioinst_handle_* functions.

Reported-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 target/s390x/misc_helper.c | 21 +++++++++++++++++++++
 1 file changed, 21 insertions(+)

diff --git a/target/s390x/misc_helper.c b/target/s390x/misc_helper.c
index 3cb942e8bb..93b0e61366 100644
--- a/target/s390x/misc_helper.c
+++ b/target/s390x/misc_helper.c
@@ -19,6 +19,7 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/main-loop.h"
 #include "cpu.h"
 #include "exec/memory.h"
 #include "qemu/host-utils.h"
@@ -551,61 +552,81 @@ uint32_t HELPER(sigp)(CPUS390XState *env, uint64_t order_code, uint32_t r1,
 void HELPER(xsch)(CPUS390XState *env, uint64_t r1)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_xsch(cpu, r1);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(csch)(CPUS390XState *env, uint64_t r1)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_csch(cpu, r1);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(hsch)(CPUS390XState *env, uint64_t r1)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_hsch(cpu, r1);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(msch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_msch(cpu, r1, inst >> 16);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(rchp)(CPUS390XState *env, uint64_t r1)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_rchp(cpu, r1);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(rsch)(CPUS390XState *env, uint64_t r1)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_rsch(cpu, r1);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(ssch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_ssch(cpu, r1, inst >> 16);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(stsch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_stsch(cpu, r1, inst >> 16);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(tsch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_tsch(cpu, r1, inst >> 16);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(chsc)(CPUS390XState *env, uint64_t inst)
 {
     S390CPU *cpu = s390_env_get_cpu(env);
+    qemu_mutex_lock_iothread();
     ioinst_handle_chsc(cpu, inst >> 16);
+    qemu_mutex_unlock_iothread();
 }
 #endif
 
-- 
2.11.0

Re: [Qemu-devel] [PATCH v3 05/11] s390x/misc_helper.c: wrap IO instructions in BQL

[Philippe Mathieu-Daudé]

On 03/07/2017 12:50 PM, Alex Bennée wrote:
> Helpers that can trigger IO events (including interrupts) need to be
> protected by the BQL. I've updated all the helpers that call into an
> ioinst_handle_* functions.
>
> Reported-by: Thomas Huth <thuth@redhat.com>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  target/s390x/misc_helper.c | 21 +++++++++++++++++++++
>  1 file changed, 21 insertions(+)
>
> diff --git a/target/s390x/misc_helper.c b/target/s390x/misc_helper.c
> index 3cb942e8bb..93b0e61366 100644
> --- a/target/s390x/misc_helper.c
> +++ b/target/s390x/misc_helper.c
> @@ -19,6 +19,7 @@
>   */
>
>  #include "qemu/osdep.h"
> +#include "qemu/main-loop.h"
>  #include "cpu.h"
>  #include "exec/memory.h"
>  #include "qemu/host-utils.h"
> @@ -551,61 +552,81 @@ uint32_t HELPER(sigp)(CPUS390XState *env, uint64_t order_code, uint32_t r1,
>  void HELPER(xsch)(CPUS390XState *env, uint64_t r1)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_xsch(cpu, r1);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(csch)(CPUS390XState *env, uint64_t r1)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_csch(cpu, r1);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(hsch)(CPUS390XState *env, uint64_t r1)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_hsch(cpu, r1);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(msch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_msch(cpu, r1, inst >> 16);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(rchp)(CPUS390XState *env, uint64_t r1)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_rchp(cpu, r1);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(rsch)(CPUS390XState *env, uint64_t r1)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_rsch(cpu, r1);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(ssch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_ssch(cpu, r1, inst >> 16);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(stsch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_stsch(cpu, r1, inst >> 16);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(tsch)(CPUS390XState *env, uint64_t r1, uint64_t inst)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_tsch(cpu, r1, inst >> 16);
> +    qemu_mutex_unlock_iothread();
>  }
>
>  void HELPER(chsc)(CPUS390XState *env, uint64_t inst)
>  {
>      S390CPU *cpu = s390_env_get_cpu(env);
> +    qemu_mutex_lock_iothread();
>      ioinst_handle_chsc(cpu, inst >> 16);
> +    qemu_mutex_unlock_iothread();
>  }
>  #endif
>
>

[Qemu-devel] [PATCH v3 06/11] target/xtensa: hold BQL for interrupt processing

[Alex Bennée]

Make sure we have the BQL held when processing interrupts.

Reported-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Acked-by: Max Filippov <jcmvbkbc@gmail.com>
---
 target/xtensa/helper.c    | 1 +
 target/xtensa/op_helper.c | 7 +++++++
 2 files changed, 8 insertions(+)

diff --git a/target/xtensa/helper.c b/target/xtensa/helper.c
index c67d715c4b..bcd0b7738d 100644
--- a/target/xtensa/helper.c
+++ b/target/xtensa/helper.c
@@ -217,6 +217,7 @@ static void handle_interrupt(CPUXtensaState *env)
     }
 }
 
+/* Called from cpu_handle_interrupt with BQL held */
 void xtensa_cpu_do_interrupt(CPUState *cs)
 {
     XtensaCPU *cpu = XTENSA_CPU(cs);
diff --git a/target/xtensa/op_helper.c b/target/xtensa/op_helper.c
index af2723445d..519fbeddd6 100644
--- a/target/xtensa/op_helper.c
+++ b/target/xtensa/op_helper.c
@@ -26,6 +26,7 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/main-loop.h"
 #include "cpu.h"
 #include "exec/helper-proto.h"
 #include "qemu/host-utils.h"
@@ -381,7 +382,11 @@ void HELPER(waiti)(CPUXtensaState *env, uint32_t pc, uint32_t intlevel)
     env->pc = pc;
     env->sregs[PS] = (env->sregs[PS] & ~PS_INTLEVEL) |
         (intlevel << PS_INTLEVEL_SHIFT);
+
+    qemu_mutex_lock_iothread();
     check_interrupts(env);
+    qemu_mutex_unlock_iothread();
+
     if (env->pending_irq_level) {
         cpu_loop_exit(CPU(xtensa_env_get_cpu(env)));
         return;
@@ -426,7 +431,9 @@ void HELPER(update_ccompare)(CPUXtensaState *env, uint32_t i)
 
 void HELPER(check_interrupts)(CPUXtensaState *env)
 {
+    qemu_mutex_lock_iothread();
     check_interrupts(env);
+    qemu_mutex_unlock_iothread();
 }
 
 void HELPER(itlb_hit_test)(CPUXtensaState *env, uint32_t vaddr)
-- 
2.11.0

[Qemu-devel] [PATCH v3 07/11] translate-all: exit cpu_restore_state early if translating

[Alex Bennée]

The translation code uses cpu_ld*_code which can trigger a tlb_fill
which if it fails will erroneously attempts a fault resolution. This
never works during translation as the TB being generated hasn't been
added yet. The target should have checked retaddr before calling
cpu_restore_state but for those that have yet to be fixed we do it
here to avoid a recursive tb_lock() under MTTCG's new locking regime.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---
v3
  - check retaddr instead
  - reword commit/comments to be clearer
---
 translate-all.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/translate-all.c b/translate-all.c
index d42d003e67..34480aebba 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -333,6 +333,19 @@ bool cpu_restore_state(CPUState *cpu, uintptr_t retaddr)
     TranslationBlock *tb;
     bool r = false;
 
+    /* A retaddr of zero is invalid so we really shouldn't have ended
+     * up here. The target code has likely forgotten to check retaddr
+     * != 0 before attempting to restore state. We return early to
+     * avoid blowing up on a recursive tb_lock(). The target must have
+     * previously survived a failed cpu_restore_state because
+     * tb_find_pc(0) would have failed anyway. It still should be
+     * fixed though.
+     */
+
+    if (!retaddr) {
+        return r;
+    }
+
     tb_lock();
     tb = tb_find_pc(retaddr);
     if (tb) {
-- 
2.11.0

Re: [Qemu-devel] [PATCH v3 07/11] translate-all: exit cpu_restore_state early if translating

[Richard Henderson]

On 03/08/2017 02:50 AM, Alex Bennée wrote:
> The translation code uses cpu_ld*_code which can trigger a tlb_fill
> which if it fails will erroneously attempts a fault resolution. This
> never works during translation as the TB being generated hasn't been
> added yet. The target should have checked retaddr before calling
> cpu_restore_state but for those that have yet to be fixed we do it
> here to avoid a recursive tb_lock() under MTTCG's new locking regime.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Reviewed-by: Richard Henderson <rth@twiddle.net>


r~

[Qemu-devel] [PATCH v3 08/11] target/mips: hold BQL for timer interrupts

[Alex Bennée]

From: Yongbok Kim <yongbok.kim@imgtec.com>

Hold BQL when accessing timer which can cause interrupts

Signed-off-by: Yongbok Kim <yongbok.kim@imgtec.com>
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 target/mips/op_helper.c | 21 ++++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

diff --git a/target/mips/op_helper.c b/target/mips/op_helper.c
index b683fcb025..e5f3ea4042 100644
--- a/target/mips/op_helper.c
+++ b/target/mips/op_helper.c
@@ -17,6 +17,7 @@
  * License along with this library; if not, see <http://www.gnu.org/licenses/>.
  */
 #include "qemu/osdep.h"
+#include "qemu/main-loop.h"
 #include "cpu.h"
 #include "qemu/host-utils.h"
 #include "exec/helper-proto.h"
@@ -827,7 +828,11 @@ target_ulong helper_mftc0_tcschefback(CPUMIPSState *env)
 
 target_ulong helper_mfc0_count(CPUMIPSState *env)
 {
-    return (int32_t)cpu_mips_get_count(env);
+    int32_t count;
+    qemu_mutex_lock_iothread();
+    count = (int32_t) cpu_mips_get_count(env);
+    qemu_mutex_unlock_iothread();
+    return count;
 }
 
 target_ulong helper_mftc0_entryhi(CPUMIPSState *env)
@@ -1375,7 +1380,9 @@ void helper_mtc0_hwrena(CPUMIPSState *env, target_ulong arg1)
 
 void helper_mtc0_count(CPUMIPSState *env, target_ulong arg1)
 {
+    qemu_mutex_lock_iothread();
     cpu_mips_store_count(env, arg1);
+    qemu_mutex_unlock_iothread();
 }
 
 void helper_mtc0_entryhi(CPUMIPSState *env, target_ulong arg1)
@@ -1424,7 +1431,9 @@ void helper_mttc0_entryhi(CPUMIPSState *env, target_ulong arg1)
 
 void helper_mtc0_compare(CPUMIPSState *env, target_ulong arg1)
 {
+    qemu_mutex_lock_iothread();
     cpu_mips_store_compare(env, arg1);
+    qemu_mutex_unlock_iothread();
 }
 
 void helper_mtc0_status(CPUMIPSState *env, target_ulong arg1)
@@ -1475,7 +1484,9 @@ void helper_mtc0_srsctl(CPUMIPSState *env, target_ulong arg1)
 
 void helper_mtc0_cause(CPUMIPSState *env, target_ulong arg1)
 {
+    qemu_mutex_lock_iothread();
     cpu_mips_store_cause(env, arg1);
+    qemu_mutex_unlock_iothread();
 }
 
 void helper_mttc0_cause(CPUMIPSState *env, target_ulong arg1)
@@ -2296,12 +2307,16 @@ target_ulong helper_rdhwr_synci_step(CPUMIPSState *env)
 
 target_ulong helper_rdhwr_cc(CPUMIPSState *env)
 {
+    int32_t count;
     check_hwrena(env, 2, GETPC());
 #ifdef CONFIG_USER_ONLY
-    return env->CP0_Count;
+    count = env->CP0_Count;
 #else
-    return (int32_t)cpu_mips_get_count(env);
+    qemu_mutex_lock_iothread();
+    count = (int32_t)cpu_mips_get_count(env);
+    qemu_mutex_unlock_iothread();
 #endif
+    return count;
 }
 
 target_ulong helper_rdhwr_ccres(CPUMIPSState *env)
-- 
2.11.0

[Qemu-devel] [PATCH v3 09/11] target-i386: defer VMEXIT to do_interrupt

[Alex Bennée]

From: Paolo Bonzini <pbonzini@redhat.com>

Paths through the softmmu code during code generation now need to be audited
to check for double locking of tb_lock.  In particular, VMEXIT can take tb_lock
through cpu_vmexit -> cpu_x86_update_cr4 -> tlb_flush.

To avoid this, split VMEXIT delivery in two parts, similar to what is done with
exceptions.  cpu_vmexit only records the VMEXIT exit code and information, and
cc->do_interrupt can then deliver it when it is safe to take the lock.

Reported-by: Alexander Boettcher <alexander.boettcher@genode-labs.com>
Suggested-by: Richard Henderson <rth@twiddle.net>
Tested-by: Alexander Boettcher <alexander.boettcher@genode-labs.com>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 target/i386/cpu.h        |  2 ++
 target/i386/seg_helper.c | 20 +++++++++++---------
 target/i386/svm_helper.c | 22 +++++++++++++---------
 3 files changed, 26 insertions(+), 18 deletions(-)

diff --git a/target/i386/cpu.h b/target/i386/cpu.h
index fb09aee7f8..406cb24301 100644
--- a/target/i386/cpu.h
+++ b/target/i386/cpu.h
@@ -697,6 +697,7 @@ typedef uint32_t FeatureWordArray[FEATURE_WORDS];
 
 #define EXCP_SYSCALL    0x100 /* only happens in user only emulation
                                  for syscall instruction */
+#define EXCP_VMEXIT     0x100
 
 /* i386-specific interrupt pending bits.  */
 #define CPU_INTERRUPT_POLL      CPU_INTERRUPT_TGT_EXT_1
@@ -1632,6 +1633,7 @@ void cpu_svm_check_intercept_param(CPUX86State *env1, uint32_t type,
                                    uint64_t param, uintptr_t retaddr);
 void cpu_vmexit(CPUX86State *nenv, uint32_t exit_code, uint64_t exit_info_1,
                 uintptr_t retaddr);
+void do_vmexit(CPUX86State *env, uint32_t exit_code, uint64_t exit_info_1);
 
 /* seg_helper.c */
 void do_interrupt_x86_hardirq(CPUX86State *env, int intno, int is_hw);
diff --git a/target/i386/seg_helper.c b/target/i386/seg_helper.c
index 5c845dc25c..0374031ea2 100644
--- a/target/i386/seg_helper.c
+++ b/target/i386/seg_helper.c
@@ -1297,15 +1297,17 @@ void x86_cpu_do_interrupt(CPUState *cs)
     /* successfully delivered */
     env->old_exception = -1;
 #else
-    /* simulate a real cpu exception. On i386, it can
-       trigger new exceptions, but we do not handle
-       double or triple faults yet. */
-    do_interrupt_all(cpu, cs->exception_index,
-                     env->exception_is_int,
-                     env->error_code,
-                     env->exception_next_eip, 0);
-    /* successfully delivered */
-    env->old_exception = -1;
+    if (cs->exception_index >= EXCP_VMEXIT) {
+        assert(env->old_exception == -1);
+        do_vmexit(env, cs->exception_index - EXCP_VMEXIT, env->error_code);
+    } else {
+        do_interrupt_all(cpu, cs->exception_index,
+                         env->exception_is_int,
+                         env->error_code,
+                         env->exception_next_eip, 0);
+        /* successfully delivered */
+        env->old_exception = -1;
+    }
 #endif
 }
 
diff --git a/target/i386/svm_helper.c b/target/i386/svm_helper.c
index 78d8df4af6..59e8b5091c 100644
--- a/target/i386/svm_helper.c
+++ b/target/i386/svm_helper.c
@@ -580,12 +580,10 @@ void helper_svm_check_io(CPUX86State *env, uint32_t port, uint32_t param,
     }
 }
 
-/* Note: currently only 32 bits of exit_code are used */
 void cpu_vmexit(CPUX86State *env, uint32_t exit_code, uint64_t exit_info_1,
                 uintptr_t retaddr)
 {
     CPUState *cs = CPU(x86_env_get_cpu(env));
-    uint32_t int_ctl;
 
     if (retaddr) {
         cpu_restore_state(cs, retaddr);
@@ -598,6 +596,19 @@ void cpu_vmexit(CPUX86State *env, uint32_t exit_code, uint64_t exit_info_1,
                                                    control.exit_info_2)),
                   env->eip);
 
+    cs->exception_index = EXCP_VMEXIT + exit_code;
+    env->error_code = exit_info_1;
+
+    /* remove any pending exception */
+    env->old_exception = -1;
+    cpu_loop_exit(cs);
+}
+
+void do_vmexit(CPUX86State *env, uint32_t exit_code, uint64_t exit_info_1)
+{
+    CPUState *cs = CPU(x86_env_get_cpu(env));
+    uint32_t int_ctl;
+
     if (env->hflags & HF_INHIBIT_IRQ_MASK) {
         x86_stl_phys(cs,
                  env->vm_vmcb + offsetof(struct vmcb, control.int_state),
@@ -759,13 +770,6 @@ void cpu_vmexit(CPUX86State *env, uint32_t exit_code, uint64_t exit_info_1,
     /* If the host's rIP reloaded by #VMEXIT is outside the limit of the
        host's code segment or non-canonical (in the case of long mode), a
        #GP fault is delivered inside the host. */
-
-    /* remove any pending exception */
-    cs->exception_index = -1;
-    env->error_code = 0;
-    env->old_exception = -1;
-
-    cpu_loop_exit(cs);
 }
 
 #endif
-- 
2.11.0

Re: [Qemu-devel] [PATCH v3 09/11] target-i386: defer VMEXIT to do_interrupt

[Richard Henderson]

On 03/08/2017 02:50 AM, Alex Bennée wrote:
> From: Paolo Bonzini <pbonzini@redhat.com>
>
> Paths through the softmmu code during code generation now need to be audited
> to check for double locking of tb_lock.  In particular, VMEXIT can take tb_lock
> through cpu_vmexit -> cpu_x86_update_cr4 -> tlb_flush.
>
> To avoid this, split VMEXIT delivery in two parts, similar to what is done with
> exceptions.  cpu_vmexit only records the VMEXIT exit code and information, and
> cc->do_interrupt can then deliver it when it is safe to take the lock.
>
> Reported-by: Alexander Boettcher <alexander.boettcher@genode-labs.com>
> Suggested-by: Richard Henderson <rth@twiddle.net>
> Tested-by: Alexander Boettcher <alexander.boettcher@genode-labs.com>
> Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  target/i386/cpu.h        |  2 ++
>  target/i386/seg_helper.c | 20 +++++++++++---------
>  target/i386/svm_helper.c | 22 +++++++++++++---------
>  3 files changed, 26 insertions(+), 18 deletions(-)

Reviewed-by: Richard Henderson <rth@twiddle.net>


r~

[Qemu-devel] [PATCH v3 10/11] target/arm/helper: make it clear the EC field is also in hex

[Alex Bennée]

..just like the rest of the displayed ESR register. Otherwise people
might scratch their heads if a not obviously hex number is displayed
for the EC field.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
Reviewed-by: KONRAD Frederic <fred.konrad@greensocs.com>
---
 target/arm/helper.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/target/arm/helper.c b/target/arm/helper.c
index 3f4211b572..76b608f0ba 100644
--- a/target/arm/helper.c
+++ b/target/arm/helper.c
@@ -6857,7 +6857,7 @@ void arm_cpu_do_interrupt(CPUState *cs)
                   new_el);
     if (qemu_loglevel_mask(CPU_LOG_INT)
         && !excp_is_internal(cs->exception_index)) {
-        qemu_log_mask(CPU_LOG_INT, "...with ESR %x/0x%" PRIx32 "\n",
+        qemu_log_mask(CPU_LOG_INT, "...with ESR 0x%x/0x%" PRIx32 "\n",
                       env->exception.syndrome >> ARM_EL_EC_SHIFT,
                       env->exception.syndrome);
     }
-- 
2.11.0

Re: [Qemu-devel] [Qemu-arm] [PATCH v3 10/11] target/arm/helper: make it clear the EC field is also in hex

[Philippe Mathieu-Daudé]

On 03/07/2017 12:50 PM, Alex Bennée wrote:
> ..just like the rest of the displayed ESR register. Otherwise people
> might scratch their heads if a not obviously hex number is displayed
> for the EC field.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
> Reviewed-by: KONRAD Frederic <fred.konrad@greensocs.com>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  target/arm/helper.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/target/arm/helper.c b/target/arm/helper.c
> index 3f4211b572..76b608f0ba 100644
> --- a/target/arm/helper.c
> +++ b/target/arm/helper.c
> @@ -6857,7 +6857,7 @@ void arm_cpu_do_interrupt(CPUState *cs)
>                    new_el);
>      if (qemu_loglevel_mask(CPU_LOG_INT)
>          && !excp_is_internal(cs->exception_index)) {
> -        qemu_log_mask(CPU_LOG_INT, "...with ESR %x/0x%" PRIx32 "\n",
> +        qemu_log_mask(CPU_LOG_INT, "...with ESR 0x%x/0x%" PRIx32 "\n",
>                        env->exception.syndrome >> ARM_EL_EC_SHIFT,
>                        env->exception.syndrome);
>      }
>

[Qemu-devel] [PATCH v3 11/11] hw/intc/arm_gic: modernise the DPRINTF

[Alex Bennée]

While I was debugging the icount issues I realised a bunch of the
messages look quite similar. I've fixed this by including __func__ in
the debug print. At the same time I move the a modern if (GATE) style
printf which ensures the compiler can check for format string errors
even if the code gets optimised away in the non-DEBUG_GIC case.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
---
 hw/intc/arm_gic.c | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/hw/intc/arm_gic.c b/hw/intc/arm_gic.c
index 8e5a9d8a3e..b305d9032a 100644
--- a/hw/intc/arm_gic.c
+++ b/hw/intc/arm_gic.c
@@ -26,15 +26,20 @@
 #include "qemu/log.h"
 #include "trace.h"
 
-//#define DEBUG_GIC
+/* #define DEBUG_GIC */
 
 #ifdef DEBUG_GIC
-#define DPRINTF(fmt, ...) \
-do { fprintf(stderr, "arm_gic: " fmt , ## __VA_ARGS__); } while (0)
+#define DEBUG_GIC_GATE 1
 #else
-#define DPRINTF(fmt, ...) do {} while(0)
+#define DEBUG_GIC_GATE 0
 #endif
 
+#define DPRINTF(fmt, ...) do {                                          \
+        if (DEBUG_GIC_GATE) {                                           \
+            fprintf(stderr, "%s: " fmt, __func__, ## __VA_ARGS__);      \
+        }                                                               \
+    } while (0)
+
 static const uint8_t gic_id_11mpcore[] = {
     0x00, 0x00, 0x00, 0x00, 0x90, 0x13, 0x04, 0x00, 0x0d, 0xf0, 0x05, 0xb1
 };
-- 
2.11.0

Re: [Qemu-devel] [Qemu-arm] [PATCH v3 11/11] hw/intc/arm_gic: modernise the DPRINTF

[Philippe Mathieu-Daudé]

On 03/07/2017 12:50 PM, Alex Bennée wrote:
> While I was debugging the icount issues I realised a bunch of the
> messages look quite similar. I've fixed this by including __func__ in
> the debug print. At the same time I move the a modern if (GATE) style
> printf which ensures the compiler can check for format string errors
> even if the code gets optimised away in the non-DEBUG_GIC case.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Reviewed-by: Peter Maydell <peter.maydell@linaro.org>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  hw/intc/arm_gic.c | 13 +++++++++----
>  1 file changed, 9 insertions(+), 4 deletions(-)
>
> diff --git a/hw/intc/arm_gic.c b/hw/intc/arm_gic.c
> index 8e5a9d8a3e..b305d9032a 100644
> --- a/hw/intc/arm_gic.c
> +++ b/hw/intc/arm_gic.c
> @@ -26,15 +26,20 @@
>  #include "qemu/log.h"
>  #include "trace.h"
>
> -//#define DEBUG_GIC
> +/* #define DEBUG_GIC */
>
>  #ifdef DEBUG_GIC
> -#define DPRINTF(fmt, ...) \
> -do { fprintf(stderr, "arm_gic: " fmt , ## __VA_ARGS__); } while (0)
> +#define DEBUG_GIC_GATE 1
>  #else
> -#define DPRINTF(fmt, ...) do {} while(0)
> +#define DEBUG_GIC_GATE 0
>  #endif
>
> +#define DPRINTF(fmt, ...) do {                                          \
> +        if (DEBUG_GIC_GATE) {                                           \
> +            fprintf(stderr, "%s: " fmt, __func__, ## __VA_ARGS__);      \
> +        }                                                               \
> +    } while (0)
> +
>  static const uint8_t gic_id_11mpcore[] = {
>      0x00, 0x00, 0x00, 0x00, 0x90, 0x13, 0x04, 0x00, 0x0d, 0xf0, 0x05, 0xb1
>  };
>

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pranith Kumar]

Hi Alex,

On Tue, Mar 7, 2017 at 10:50 AM, Alex Bennée <alex.bennee@linaro.org> wrote:
> Hi,
>
> This is the latest iteration of fixes for problems introduced by
> MTTCG. Aside from the usual slew of addressing review comments and
> applying tags I've also pulled in Yongbok Kim's MIPS patch (to replace
> mine) and Paolo's VMEXIT fix for the problem reported by Alexander
> Boettcher.
>
> Unless anyone shouts I'll wrap these up into a pull request for Peter
> tomorrow.


Can you also pick up this patch? I am not sure who else will.

http://patchwork.ozlabs.org/patch/733293/

Thanks,
-- 
Pranith

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pranith Kumar]

On Wed, Mar 8, 2017 at 2:39 AM, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> Pranith Kumar <bobby.prani@gmail.com> writes:
>
>> Hi Alex,
>>
>> On Tue, Mar 7, 2017 at 10:50 AM, Alex Bennée <alex.bennee@linaro.org> wrote:
>>> Hi,
>>>
>>> This is the latest iteration of fixes for problems introduced by
>>> MTTCG. Aside from the usual slew of addressing review comments and
>>> applying tags I've also pulled in Yongbok Kim's MIPS patch (to replace
>>> mine) and Paolo's VMEXIT fix for the problem reported by Alexander
>>> Boettcher.
>>>
>>> Unless anyone shouts I'll wrap these up into a pull request for Peter
>>> tomorrow.
>>
>>
>> Can you also pick up this patch? I am not sure who else will.
>>
>> http://patchwork.ozlabs.org/patch/733293/
>
> Does the problem only exhibit itself with --accel tcg,thread=multi? I
> was figuring it would go in with a larger x86 MTTCG enabling patch set
> post 2.9. If it can occur with the defaults now I'll happily add it
> to the pullreq I'm preparing.
>

It happens only with thread=multi, so I guess later on is OK.

Thanks,
-- 
Pranith

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

Hi,

> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
> 
> The next thing on my list it to look at the icount problems and review
> Paolo's fixes for it. However those fixes should go in a separate
> series and I assume via Paolo's tree.
 
Do you mean those problems that completely broke icount?
Are you going to fix it?


> Alex Bennée (9):
>   vl/cpus: be smarter with icount and MTTCG
>   target/i386/cpu.h: declare TCG_GUEST_DEFAULT_MO
>   cpus.c: add additional error_report when !TARGET_SUPPORT_MTTCG
>   sparc/sparc64: grab BQL before calling cpu_check_irqs
>   s390x/misc_helper.c: wrap IO instructions in BQL
>   target/xtensa: hold BQL for interrupt processing
>   translate-all: exit cpu_restore_state early if translating
>   target/arm/helper: make it clear the EC field is also in hex
>   hw/intc/arm_gic: modernise the DPRINTF
> 
> Paolo Bonzini (1):
>   target-i386: defer VMEXIT to do_interrupt
> 
> Yongbok Kim (1):
>   target/mips: hold BQL for timer interrupts


Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

> Hi,
>
>> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
>>
>> The next thing on my list it to look at the icount problems and review
>> Paolo's fixes for it. However those fixes should go in a separate
>> series and I assume via Paolo's tree.
>
> Do you mean those problems that completely broke icount?

Completely broke is a bit strong. Certainly I tested icount on my
patches but I missed the pathological failure mode that led to the
interaction between the BQL lock breaking patch and running a real
guest. It didn't break icount so much as slow down guests so much they
never got round to finishing their IRQ handling.

That certainly seems to be fixed by Paolo's patches.

> Are you going to fix it?

Yes. It is certainly not intentional to regress icount and it needs to
be fixed before we release 2.9.

If you can point me towards the record/replay test cases I'll make sure
I run them on the updated series.

>
>
>> Alex Bennée (9):
>>   vl/cpus: be smarter with icount and MTTCG
>>   target/i386/cpu.h: declare TCG_GUEST_DEFAULT_MO
>>   cpus.c: add additional error_report when !TARGET_SUPPORT_MTTCG
>>   sparc/sparc64: grab BQL before calling cpu_check_irqs
>>   s390x/misc_helper.c: wrap IO instructions in BQL
>>   target/xtensa: hold BQL for interrupt processing
>>   translate-all: exit cpu_restore_state early if translating
>>   target/arm/helper: make it clear the EC field is also in hex
>>   hw/intc/arm_gic: modernise the DPRINTF
>>
>> Paolo Bonzini (1):
>>   target-i386: defer VMEXIT to do_interrupt
>>
>> Yongbok Kim (1):
>>   target/mips: hold BQL for timer interrupts
>
>
> Pavel Dovgalyuk


--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
> request@listserver.greensocs.com]
> >>
> >> The next thing on my list it to look at the icount problems and review
> >> Paolo's fixes for it. However those fixes should go in a separate
> >> series and I assume via Paolo's tree.
> >
> > Do you mean those problems that completely broke icount?
> 
> Completely broke is a bit strong. Certainly I tested icount on my
> patches but I missed the pathological failure mode that led to the
> interaction between the BQL lock breaking patch and running a real
> guest. It didn't break icount so much as slow down guests so much they
> never got round to finishing their IRQ handling.

That might look as slowing down in regular icount mode.
But it becomes non-deterministic in record/replay mode.
Therefore none of the recorded scenarios may be replayed.

I tried the simplest command lines:

qemu-system-i386.exe -icount shift=7,rr=record,rrfile=replay.bin -net none 

qemu-system-i386.exe -icount shift=7,rr=replay,rrfile=replay.bin -net none

First one was used to record execution until BIOS will print its startup info.
The second one is for replay, but it can replay about 200000 instructions
until the problems with icount manifest itself - the execution does not proceed.

> That certainly seems to be fixed by Paolo's patches.
> 
> > Are you going to fix it?
> 
> Yes. It is certainly not intentional to regress icount and it needs to
> be fixed before we release 2.9.
> 
> If you can point me towards the record/replay test cases I'll make sure
> I run them on the updated series.


Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>> request@listserver.greensocs.com]
>> >>
>> >> The next thing on my list it to look at the icount problems and review
>> >> Paolo's fixes for it. However those fixes should go in a separate
>> >> series and I assume via Paolo's tree.
>> >
>> > Do you mean those problems that completely broke icount?
>>
>> Completely broke is a bit strong. Certainly I tested icount on my
>> patches but I missed the pathological failure mode that led to the
>> interaction between the BQL lock breaking patch and running a real
>> guest. It didn't break icount so much as slow down guests so much they
>> never got round to finishing their IRQ handling.
>
> That might look as slowing down in regular icount mode.
> But it becomes non-deterministic in record/replay mode.
> Therefore none of the recorded scenarios may be replayed.
>
> I tried the simplest command lines:
>
> qemu-system-i386.exe -icount shift=7,rr=record,rrfile=replay.bin -net
> none

Running this against 2421f381dc (pre-merge of MTTCG) from the source
tree generates no output. My command is on Linux:

  /x86_64-softmmu/qemu-system-x86_64 -icount shift=7,rr=record,rrfile=replay.bin -net none

Do I need to specify the BIOS manually?

>
> qemu-system-i386.exe -icount shift=7,rr=replay,rrfile=replay.bin -net none
>
> First one was used to record execution until BIOS will print its startup info.
> The second one is for replay, but it can replay about 200000 instructions
> until the problems with icount manifest itself - the execution does
> not proceed.

What error message does it give? How do you know how many instructions
have been executed?

I ran the following test on both pre-mttcg-merge and my current HEAD
which includes Paolo's fix series:

 ./arm-softmmu/qemu-system-arm -machine type=virt \
    -display none -smp 1 -m 4096 -cpu cortex-a15 \
    -kernel ../images/aarch32-current-linux-initrd-guest.img
    -append "console=ttyAMA0" -serial mon:stdio \
    -net none \
    -icount shift=7,rr=record,rrfile=replay.bin

And then:

 ./arm-softmmu/qemu-system-arm -machine type=virt \
    -display none -smp 1 -m 4096 -cpu cortex-a15 \
    -kernel ../images/aarch32-current-linux-initrd-guest.img
    -append "console=ttyAMA0" -serial mon:stdio \
    -net none \
    -icount shift=7,rr=replay,rrfile=replay.bin

And they both ran the same. However I kept running into:

 [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
qemu-system-arm: Missing character write event in the replay log

This seems to be a pre-existing

>
>> That certainly seems to be fixed by Paolo's patches.
>>
>> > Are you going to fix it?
>>
>> Yes. It is certainly not intentional to regress icount and it needs to
>> be fixed before we release 2.9.
>>
>> If you can point me towards the record/replay test cases I'll make sure
>> I run them on the updated series.
>
>
> Pavel Dovgalyuk


--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
> >> request@listserver.greensocs.com]
> >> >>
> >> >> The next thing on my list it to look at the icount problems and review
> >> >> Paolo's fixes for it. However those fixes should go in a separate
> >> >> series and I assume via Paolo's tree.
> >> >
> >> > Do you mean those problems that completely broke icount?
> >>
> >> Completely broke is a bit strong. Certainly I tested icount on my
> >> patches but I missed the pathological failure mode that led to the
> >> interaction between the BQL lock breaking patch and running a real
> >> guest. It didn't break icount so much as slow down guests so much they
> >> never got round to finishing their IRQ handling.
> >
> > That might look as slowing down in regular icount mode.
> > But it becomes non-deterministic in record/replay mode.
> > Therefore none of the recorded scenarios may be replayed.
> >
> > I tried the simplest command lines:
> >
> > qemu-system-i386.exe -icount shift=7,rr=record,rrfile=replay.bin -net
> > none
> 
> Running this against 2421f381dc (pre-merge of MTTCG) from the source
> tree generates no output. My command is on Linux:
> 
>   /x86_64-softmmu/qemu-system-x86_64 -icount shift=7,rr=record,rrfile=replay.bin -net none
> 
> Do I need to specify the BIOS manually?

No, this command line works well for me. BIOS executes and shows some messages.
Do you have any graphical output for QEMU?

> > qemu-system-i386.exe -icount shift=7,rr=replay,rrfile=replay.bin -net none
> >
> > First one was used to record execution until BIOS will print its startup info.
> > The second one is for replay, but it can replay about 200000 instructions
> > until the problems with icount manifest itself - the execution does
> > not proceed.
> 
> What error message does it give? How do you know how many instructions
> have been executed?

It hangs after executing about 200000 instructions.
I checked -d exec logs.

> I ran the following test on both pre-mttcg-merge and my current HEAD
> which includes Paolo's fix series:
> 
>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>     -append "console=ttyAMA0" -serial mon:stdio \
>     -net none \
>     -icount shift=7,rr=record,rrfile=replay.bin
> 
> And then:
> 
>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>     -append "console=ttyAMA0" -serial mon:stdio \
>     -net none \
>     -icount shift=7,rr=replay,rrfile=replay.bin
> 
> And they both ran the same. However I kept running into:
> 
>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
> qemu-system-arm: Missing character write event in the replay log
> 
> This seems to be a pre-existing

Does it mean that qemu-arm platform includes some serial devices that were
not detected by the replay?

Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>> >> request@listserver.greensocs.com]
>> >> >>
>> >> >> The next thing on my list it to look at the icount problems and review
>> >> >> Paolo's fixes for it. However those fixes should go in a separate
>> >> >> series and I assume via Paolo's tree.
>> >> >
>> >> > Do you mean those problems that completely broke icount?
>> >>
>> >> Completely broke is a bit strong. Certainly I tested icount on my
>> >> patches but I missed the pathological failure mode that led to the
>> >> interaction between the BQL lock breaking patch and running a real
>> >> guest. It didn't break icount so much as slow down guests so much they
>> >> never got round to finishing their IRQ handling.
>> >
>> > That might look as slowing down in regular icount mode.
>> > But it becomes non-deterministic in record/replay mode.
>> > Therefore none of the recorded scenarios may be replayed.
>> >
>> > I tried the simplest command lines:
>> >
>> > qemu-system-i386.exe -icount shift=7,rr=record,rrfile=replay.bin -net
>> > none
>>
>> Running this against 2421f381dc (pre-merge of MTTCG) from the source
>> tree generates no output. My command is on Linux:
>>
>>   /x86_64-softmmu/qemu-system-x86_64 -icount shift=7,rr=record,rrfile=replay.bin -net none
>>
>> Do I need to specify the BIOS manually?
>
> No, this command line works well for me. BIOS executes and shows some messages.
> Do you have any graphical output for QEMU?

Ahh I was running remotely. OK I can now get output on the graphics
display and the described hang. I'll have a look at it.

>
>> > qemu-system-i386.exe -icount shift=7,rr=replay,rrfile=replay.bin -net none
>> >
>> > First one was used to record execution until BIOS will print its startup info.
>> > The second one is for replay, but it can replay about 200000 instructions
>> > until the problems with icount manifest itself - the execution does
>> > not proceed.
>>
>> What error message does it give? How do you know how many instructions
>> have been executed?
>
> It hangs after executing about 200000 instructions.
> I checked -d exec logs.
>
>> I ran the following test on both pre-mttcg-merge and my current HEAD
>> which includes Paolo's fix series:
>>
>>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>>     -append "console=ttyAMA0" -serial mon:stdio \
>>     -net none \
>>     -icount shift=7,rr=record,rrfile=replay.bin
>>
>> And then:
>>
>>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>>     -append "console=ttyAMA0" -serial mon:stdio \
>>     -net none \
>>     -icount shift=7,rr=replay,rrfile=replay.bin
>>
>> And they both ran the same. However I kept running into:
>>
>>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
>> qemu-system-arm: Missing character write event in the replay log
>>
>> This seems to be a pre-existing
>
> Does it mean that qemu-arm platform includes some serial devices that were
> not detected by the replay?

It's the standard ARM platform serial port. When I read replay.txt is
said:

 * Supports i386, x86_64, and ARM hardware platforms.

Should we add some qualifications about which machine types are
supported? What is you ARM test case for record/replay?

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >
> >> I ran the following test on both pre-mttcg-merge and my current HEAD
> >> which includes Paolo's fix series:
> >>
> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >>     -net none \
> >>     -icount shift=7,rr=record,rrfile=replay.bin
> >>
> >> And then:
> >>
> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >>     -net none \
> >>     -icount shift=7,rr=replay,rrfile=replay.bin
> >>
> >> And they both ran the same. However I kept running into:
> >>
> >>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
> >> qemu-system-arm: Missing character write event in the replay log
> >>
> >> This seems to be a pre-existing
> >
> > Does it mean that qemu-arm platform includes some serial devices that were
> > not detected by the replay?
> 
> It's the standard ARM platform serial port. When I read replay.txt is
> said:
> 
>  * Supports i386, x86_64, and ARM hardware platforms.
> 
> Should we add some qualifications about which machine types are
> supported? What is you ARM test case for record/replay?

I tested on vexpress-a9 platform with Debian wheezy.

Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >
>> >> I ran the following test on both pre-mttcg-merge and my current HEAD
>> >> which includes Paolo's fix series:
>> >>
>> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>> >>     -append "console=ttyAMA0" -serial mon:stdio \
>> >>     -net none \
>> >>     -icount shift=7,rr=record,rrfile=replay.bin
>> >>
>> >> And then:
>> >>
>> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>> >>     -append "console=ttyAMA0" -serial mon:stdio \
>> >>     -net none \
>> >>     -icount shift=7,rr=replay,rrfile=replay.bin
>> >>
>> >> And they both ran the same. However I kept running into:
>> >>
>> >>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
>> >> qemu-system-arm: Missing character write event in the replay log
>> >>
>> >> This seems to be a pre-existing
>> >
>> > Does it mean that qemu-arm platform includes some serial devices that were
>> > not detected by the replay?
>>
>> It's the standard ARM platform serial port. When I read replay.txt is
>> said:
>>
>>  * Supports i386, x86_64, and ARM hardware platforms.
>>
>> Should we add some qualifications about which machine types are
>> supported? What is you ARM test case for record/replay?
>
> I tested on vexpress-a9 platform with Debian wheezy.

Thanks for that. I now have a test case that I can reproduce failures on
without needing graphics.

I've been investigating if there are any problems with the timer
processing now they have been moved into the TCG thread. The record
stage seems to work fine but I'm having difficulty figuring out why
playback freezes. It seems we get to a point where we are stuck waiting
for a suspiciously exact timer deadline:

  replay_account_executed_instructions: instructions_count reached zero
  handle_icount_deadline: deadline=471077745280
  replay_account_executed_instructions: instructions_count reached zero
  handle_icount_deadline: deadline=10000000
  [Switching to Thread 0x7fff7a7be700 (LWP 733)]

  Thread 3 "qemu-system-arm" hit Breakpoint 1, handle_icount_deadline () at /home/alex/lsrc/qemu/qemu.git/cpus.c:1184
  1184                    fprintf(stderr,"%s: no change to deadline=%ld for %ld\n",
  (gdb) c
  Continuing.
  handle_icount_deadline: no change to deadline=10000000 for 11

  Thread 3 "qemu-system-arm" hit Breakpoint 1, handle_icount_deadline () at /home/alex/lsrc/qemu/qemu.git/cpus.c:1184
  1184                    fprintf(stderr,"%s: no change to deadline=%ld for %ld\n",
  (gdb) c 10
  Will ignore next 9 crossings of breakpoint 1.  Continuing.
  handle_icount_deadline: no change to deadline=10000000 for 12
  handle_icount_deadline: no change to deadline=10000000 for 13
  handle_icount_deadline: no change to deadline=10000000 for 14
  handle_icount_deadline: no change to deadline=10000000 for 15
  handle_icount_deadline: no change to deadline=10000000 for 16
  handle_icount_deadline: no change to deadline=10000000 for 17
  handle_icount_deadline: no change to deadline=10000000 for 18
  handle_icount_deadline: no change to deadline=10000000 for 19
  handle_icount_deadline: no change to deadline=10000000 for 20
  handle_icount_deadline: no change to deadline=10000000 for 21

  (gdb) p replay_state
  $1 = {cached_clock = {1490191319270134000, 0}, current_step = 267869922, instructions_count = 0, data_kind = 12, has_unread_data = 1, file_offset = 0, block_request_id = 0}

But the timers are all enabled:

  (gdb) qemu timers
  Processing Realtime timers
    clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
  Processing Virtual timers
    clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
      timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
      timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
  Processing Host timers
    clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
  Processing Virtual RT timers
    clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808

One area I wanted to look back at was comparing the record trace from
pre-mttcg-merge to now to see if any information was missing. However
the bin file has quite a lot of noise in it from changing fields so I
was wondering do you have any sort of dumper tool for comparing the
traces? If not is the format of the trace file specified anywhere?

I found:
  #define REPLAY_VERSION              0xe02005

but couldn't find any more than that. Is the format basically just
described by the calls to replay_put_byte?

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> 
> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >
> >> >> I ran the following test on both pre-mttcg-merge and my current HEAD
> >> >> which includes Paolo's fix series:
> >> >>
> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >> >>     -net none \
> >> >>     -icount shift=7,rr=record,rrfile=replay.bin
> >> >>
> >> >> And then:
> >> >>
> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >> >>     -net none \
> >> >>     -icount shift=7,rr=replay,rrfile=replay.bin
> >> >>
> >> >> And they both ran the same. However I kept running into:
> >> >>
> >> >>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
> >> >> qemu-system-arm: Missing character write event in the replay log
> >> >>
> >> >> This seems to be a pre-existing
> >> >
> >> > Does it mean that qemu-arm platform includes some serial devices that were
> >> > not detected by the replay?
> >>
> >> It's the standard ARM platform serial port. When I read replay.txt is
> >> said:
> >>
> >>  * Supports i386, x86_64, and ARM hardware platforms.
> >>
> >> Should we add some qualifications about which machine types are
> >> supported? What is you ARM test case for record/replay?
> >
> > I tested on vexpress-a9 platform with Debian wheezy.
> 
> Thanks for that. I now have a test case that I can reproduce failures on
> without needing graphics.
> 
> I've been investigating if there are any problems with the timer
> processing now they have been moved into the TCG thread. The record
> stage seems to work fine but I'm having difficulty figuring out why
> playback freezes. It seems we get to a point where we are stuck waiting
> for a suspiciously exact timer deadline:

I've encountered the following behavior at replay stage:
- replay takes some instructions to execute (qemu_icount += counter)
- virtual timer is fired
- replay puts back unexecuted instructions (qemu_icount -= counter)

But virtual timer cannot take in account non-executed instructions (counter) and
therefore it reads only qemu_icount, which provides incorrect time.

> But the timers are all enabled:
> 
>   (gdb) qemu timers
>   Processing Realtime timers
>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
>   Processing Virtual timers
>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
>   Processing Host timers
>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
>   Processing Virtual RT timers
>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808

Timers are processed only at checkpoints recorded in the log.
When replay is stuck, probably there is a pending checkpoint in the log
and pending instructions in CPU (because iothread breaks its synchronization).

> One area I wanted to look back at was comparing the record trace from
> pre-mttcg-merge to now to see if any information was missing. However

I usually use in_asm and exec logs and also add some logging at replay checkpoints.

> the bin file has quite a lot of noise in it from changing fields so I
> was wondering do you have any sort of dumper tool for comparing the
> traces? If not is the format of the trace file specified anywhere?

Usually you cannot compare two different record/replay logs, because there
is no synchronization of the timers in different recording runs and
therefore you'll get totally different logs.

Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>
>> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> >
>> >> >> I ran the following test on both pre-mttcg-merge and my current HEAD
>> >> >> which includes Paolo's fix series:
>> >> >>
>> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
>> >> >>     -net none \
>> >> >>     -icount shift=7,rr=record,rrfile=replay.bin
>> >> >>
>> >> >> And then:
>> >> >>
>> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
>> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
>> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
>> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
>> >> >>     -net none \
>> >> >>     -icount shift=7,rr=replay,rrfile=replay.bin
>> >> >>
>> >> >> And they both ran the same. However I kept running into:
>> >> >>
>> >> >>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
>> >> >> qemu-system-arm: Missing character write event in the replay log
>> >> >>
>> >> >> This seems to be a pre-existing
>> >> >
>> >> > Does it mean that qemu-arm platform includes some serial devices that were
>> >> > not detected by the replay?
>> >>
>> >> It's the standard ARM platform serial port. When I read replay.txt is
>> >> said:
>> >>
>> >>  * Supports i386, x86_64, and ARM hardware platforms.
>> >>
>> >> Should we add some qualifications about which machine types are
>> >> supported? What is you ARM test case for record/replay?
>> >
>> > I tested on vexpress-a9 platform with Debian wheezy.
>>
>> Thanks for that. I now have a test case that I can reproduce failures on
>> without needing graphics.
>>
>> I've been investigating if there are any problems with the timer
>> processing now they have been moved into the TCG thread. The record
>> stage seems to work fine but I'm having difficulty figuring out why
>> playback freezes. It seems we get to a point where we are stuck waiting
>> for a suspiciously exact timer deadline:
>
> I've encountered the following behavior at replay stage:
> - replay takes some instructions to execute (qemu_icount += counter)
> - virtual timer is fired

This is the virtual timer based on icount not the virtual rt timer? So
under the new scheme of being processed in the vCPU loop we should only
fire this one once all execution is done (although you may exit the loop
early before icount is exhausted).

> - replay puts back unexecuted instructions (qemu_icount -= counter)
>
> But virtual timer cannot take in account non-executed instructions (counter) and
> therefore it reads only qemu_icount, which provides incorrect time.
>
>> But the timers are all enabled:
>>
>>   (gdb) qemu timers
>>   Processing Realtime timers
>>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
>>   Processing Virtual timers
>>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
>>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
>>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
>>   Processing Host timers
>>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
>>   Processing Virtual RT timers
>>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
>
> Timers are processed only at checkpoints recorded in the log.
> When replay is stuck, probably there is a pending checkpoint in the log
> and pending instructions in CPU (because iothread breaks its
> synchronization).

How does this work for instructions that sleep (like WFI)? The WFI will
cause us to exit the loop but I assume we need a "real" timer to trigger
a firing of whatever the WFI is waiting for as time according to icount
isn't advancing.

>
>> One area I wanted to look back at was comparing the record trace from
>> pre-mttcg-merge to now to see if any information was missing. However
>
> I usually use in_asm and exec logs and also add some logging at replay checkpoints.
>
>> the bin file has quite a lot of noise in it from changing fields so I
>> was wondering do you have any sort of dumper tool for comparing the
>> traces? If not is the format of the trace file specified anywhere?
>
> Usually you cannot compare two different record/replay logs, because there
> is no synchronization of the timers in different recording runs and
> therefore you'll get totally different logs.

I wasn't looking to have identical traces but I was interested in the
patterns in the logs and how they have changed. For example:

HEADER: version 0xe02005                                      | HEADER: version 0xe02006
1:EVENT_CP_INIT                                                 1:EVENT_CP_INIT
2:EVENT_CLOCK_HOST 0x14afc6687f1fc738                         | 2:EVENT_CLOCK_HOST 0x14b000644239c8d8
3:EVENT_CLOCK_HOST 0x14afc66c6ac91858                         | 3:EVENT_CLOCK_HOST 0x14b00064423a1310
4:EVENT_CP_RESET no additional data                             4:EVENT_CP_RESET no additional data
5:EVENT_CP_CLOCK_WARP_START no additional data                  5:EVENT_CP_CLOCK_WARP_START no additional data
6:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 6:EVENT_CP_CLOCK_WARP_START no additional data
7:EVENT_CP_CLOCK_WARP_START no additional data                | 7:EVENT_CP_CLOCK_VIRTUAL no additional data
8:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 8:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data
9:EVENT_CP_CLOCK_WARP_START no additional data                | 9:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data
10:EVENT_CP_CLOCK_VIRTUAL no additional data                  | 10:EVENT_INSTRUCTION 0x1000000
11:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data               11:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data
12:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data             | 12:EVENT_INSTRUCTION 0x1000000
13:EVENT_INSTRUCTION 0x1000000                                | 13:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data

There is a difference to the pattern at the start as the initial
checkpoints are layed down. I guess this is due to the interaction of
the main thread with the vCPU as they bounce the BQL with each other.

I'm wondering why we don't just do all the warp timer management in the
vCPU thread as well?

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
> request@listserver.greensocs.com]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >>
> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >> >
> >> >> >> I ran the following test on both pre-mttcg-merge and my current HEAD
> >> >> >> which includes Paolo's fix series:
> >> >> >>
> >> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >> >> >>     -net none \
> >> >> >>     -icount shift=7,rr=record,rrfile=replay.bin
> >> >> >>
> >> >> >> And then:
> >> >> >>
> >> >> >>  ./arm-softmmu/qemu-system-arm -machine type=virt \
> >> >> >>     -display none -smp 1 -m 4096 -cpu cortex-a15 \
> >> >> >>     -kernel ../images/aarch32-current-linux-initrd-guest.img
> >> >> >>     -append "console=ttyAMA0" -serial mon:stdio \
> >> >> >>     -net none \
> >> >> >>     -icount shift=7,rr=replay,rrfile=replay.bin
> >> >> >>
> >> >> >> And they both ran the same. However I kept running into:
> >> >> >>
> >> >> >>  [    3.542408] RPC: Registered tcp NFSv4.1 backchannel transport module.
> >> >> >> qemu-system-arm: Missing character write event in the replay log
> >> >> >>
> >> >> >> This seems to be a pre-existing
> >> >> >
> >> >> > Does it mean that qemu-arm platform includes some serial devices that were
> >> >> > not detected by the replay?
> >> >>
> >> >> It's the standard ARM platform serial port. When I read replay.txt is
> >> >> said:
> >> >>
> >> >>  * Supports i386, x86_64, and ARM hardware platforms.
> >> >>
> >> >> Should we add some qualifications about which machine types are
> >> >> supported? What is you ARM test case for record/replay?
> >> >
> >> > I tested on vexpress-a9 platform with Debian wheezy.
> >>
> >> Thanks for that. I now have a test case that I can reproduce failures on
> >> without needing graphics.
> >>
> >> I've been investigating if there are any problems with the timer
> >> processing now they have been moved into the TCG thread. The record
> >> stage seems to work fine but I'm having difficulty figuring out why
> >> playback freezes. It seems we get to a point where we are stuck waiting
> >> for a suspiciously exact timer deadline:
> >
> > I've encountered the following behavior at replay stage:
> > - replay takes some instructions to execute (qemu_icount += counter)
> > - virtual timer is fired
> 
> This is the virtual timer based on icount not the virtual rt timer? So

Regular virtual timer. It's value is based on icount.
virtual_rt is used for internal icount purposes.

> under the new scheme of being processed in the vCPU loop we should only
> fire this one once all execution is done (although you may exit the loop
> early before icount is exhausted).

We should stop the vCPU before processing virtual timers because:
- virtual clock depends on instruction counter
- virtual timers may change virtual hardware state

> > - replay puts back unexecuted instructions (qemu_icount -= counter)
> >
> > But virtual timer cannot take in account non-executed instructions (counter) and
> > therefore it reads only qemu_icount, which provides incorrect time.
> >
> >> But the timers are all enabled:
> >>
> >>   (gdb) qemu timers
> >>   Processing Realtime timers
> >>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
> >>   Processing Virtual timers
> >>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
> >>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
> >>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
> >>   Processing Host timers
> >>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
> >>   Processing Virtual RT timers
> >>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
> >
> > Timers are processed only at checkpoints recorded in the log.
> > When replay is stuck, probably there is a pending checkpoint in the log
> > and pending instructions in CPU (because iothread breaks its
> > synchronization).
> 
> How does this work for instructions that sleep (like WFI)? The WFI will
> cause us to exit the loop but I assume we need a "real" timer to trigger
> a firing of whatever the WFI is waiting for as time according to icount
> isn't advancing.

This is virtual_rt for. It advances even when vCPU is stopped.

> >> One area I wanted to look back at was comparing the record trace from
> >> pre-mttcg-merge to now to see if any information was missing. However
> >
> > I usually use in_asm and exec logs and also add some logging at replay checkpoints.
> >
> >> the bin file has quite a lot of noise in it from changing fields so I
> >> was wondering do you have any sort of dumper tool for comparing the
> >> traces? If not is the format of the trace file specified anywhere?
> >
> > Usually you cannot compare two different record/replay logs, because there
> > is no synchronization of the timers in different recording runs and
> > therefore you'll get totally different logs.
> 
> I wasn't looking to have identical traces but I was interested in the
> patterns in the logs and how they have changed. For example:
> 
> HEADER: version 0xe02005                                      | HEADER: version 0xe02006
> 1:EVENT_CP_INIT                                                 1:EVENT_CP_INIT
> 2:EVENT_CLOCK_HOST 0x14afc6687f1fc738                         | 2:EVENT_CLOCK_HOST
> 0x14b000644239c8d8
> 3:EVENT_CLOCK_HOST 0x14afc66c6ac91858                         | 3:EVENT_CLOCK_HOST
> 0x14b00064423a1310
> 4:EVENT_CP_RESET no additional data                             4:EVENT_CP_RESET no additional
> data
> 5:EVENT_CP_CLOCK_WARP_START no additional data                  5:EVENT_CP_CLOCK_WARP_START no
> additional data
> 6:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 6:EVENT_CP_CLOCK_WARP_START no
> additional data
> 7:EVENT_CP_CLOCK_WARP_START no additional data                | 7:EVENT_CP_CLOCK_VIRTUAL no
> additional data
> 8:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 8:EVENT_CP_CLOCK_WARP_ACCOUNT
> no additional data
> 9:EVENT_CP_CLOCK_WARP_START no additional data                | 9:EVENT_CP_CLOCK_WARP_ACCOUNT
> no additional data
> 10:EVENT_CP_CLOCK_VIRTUAL no additional data                  | 10:EVENT_INSTRUCTION 0x1000000
> 11:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data               11:EVENT_CP_CLOCK_WARP_ACCOUNT
> no additional data
> 12:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data             | 12:EVENT_INSTRUCTION 0x1000000
> 13:EVENT_INSTRUCTION 0x1000000                                | 13:EVENT_CP_CLOCK_WARP_ACCOUNT
> no additional data
> 
> There is a difference to the pattern at the start as the initial
> checkpoints are layed down. I guess this is due to the interaction of
> the main thread with the vCPU as they bounce the BQL with each other.

Yes, this may be caused by changed interaction between the threads.

> I'm wondering why we don't just do all the warp timer management in the
> vCPU thread as well?

Because vCPU may sleep and we'll have to setup some timer (virtual_rt as now) anyway.



By the way, I made small description of the replay log format
to be later included into docs/replay.txt:

Record/replay log consits of the header and the sequence of execution
events. The header includes 4-byte replay version id and 8-byte reserved
field. Version is updated every time replay log format changes to prevent
using replay log created by another build of qemu.

The sequence of the events describes virtual machine state changes.
It includes all non-deterministic inputs of VM, synchronization marks and
instruction counts used to correctly inject inputs at replay.

Synchronization marks (checkpoints) are used for synchronizing qemu threads
that perform operations with virtual hardware. These operations may change
system's state (e.g., change some register or generate interrupt) and
therefore should execute synchronously with CPU thread.

Every event in the log includes 1-byte event id and optional arguments.
When argument is an array, it is stored as 4-byte array length
and corresponding number of bytes with data.
Here is the list of events that are written into the log:

 - EVENT_INSTRUCTION. Instructions executed since last event.
   Argument: 4-byte number of executed instructions.
 - EVENT_INTERRUPT. Used to synchronize interrupt processing.
 - EVENT_EXCEPTION. Used to synchronize exception handling.
 - EVENT_ASYNC. This is a group of events. They are always processed
   together with checkpoints. When such an event is generated, it is
   stored in the queue and processed only when checkpoint occurs.
   Every such event is followed by 1-byte checkpoint id and 1-byte
   async event id from the following list:
     - REPLAY_ASYNC_EVENT_BH. Bottom-half callback. This event synchronizes
       callbacks that affect virtual machine state, but normally called
       asyncronously.
       Argument: 8-byte operation id.
     - REPLAY_ASYNC_EVENT_INPUT. Input device event. Contains
       parameters of keyboard and mouse input operations
       (key press/release, mouse pointer movement).
       Arguments: 9-16 bytes depending of input event.
     - REPLAY_ASYNC_EVENT_INPUT_SYNC. Internal input synchronization event.
     - REPLAY_ASYNC_EVENT_CHAR_READ. Character (e.g., serial port) device input
       initiated by the sender.
       Arguments: 1-byte character device id.
                  Array with bytes were read.
     - REPLAY_ASYNC_EVENT_BLOCK. Block device operation. Used to synchronize
       operations with disk and flash drives with CPU.
       Argument: 8-byte operation id.
     - REPLAY_ASYNC_EVENT_NET. Incoming network packet.
       Arguments: 1-byte network adapter id.
                  4-byte packet flags.
                  Array with packet bytes.
 - EVENT_SHUTDOWN. Occurs when user sends shutdown event to qemu,
   e.g., by closing the window.
 - EVENT_CHAR_WRITE. Used to synchronize character output operations.
   Arguments: 4-byte output function return value.
              4-byte offset in the output array.
 - EVENT_CHAR_READ_ALL. Used to synchronize character input operations,
   initiated by qemu.
   Argument: Array with bytes that were read.
 - EVENT_CHAR_READ_ALL_ERROR. Unsuccessful character input operation,
   initiated by qemu.
   Argument: 4-byte error code.
 - EVENT_CLOCK + clock_id. Group of events for host clock read operations.
   Argument: 8-byte clock value.
 - EVENT_CHECKPOINT + checkpoint_id. Checkpoint for synchronization of
   CPU, internal threads, and asynchronous input events. May be followed
   by one or more EVENT_ASYNC events.
 - EVENT_END. Last event in the log.


Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>> request@listserver.greensocs.com]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
<snip>
>> >> > I tested on vexpress-a9 platform with Debian wheezy.
>> >>
>> >> Thanks for that. I now have a test case that I can reproduce failures on
>> >> without needing graphics.
>> >>
>> >> I've been investigating if there are any problems with the timer
>> >> processing now they have been moved into the TCG thread. The record
>> >> stage seems to work fine but I'm having difficulty figuring out why
>> >> playback freezes. It seems we get to a point where we are stuck waiting
>> >> for a suspiciously exact timer deadline:
>> >
>> > I've encountered the following behavior at replay stage:
>> > - replay takes some instructions to execute (qemu_icount += counter)
>> > - virtual timer is fired
>>
>> This is the virtual timer based on icount not the virtual rt timer? So
>
> Regular virtual timer. It's value is based on icount.
> virtual_rt is used for internal icount purposes.

And this is where the clock warps come in? The bias brings the
virtual_rt time forward because execution is waiting for some external
event to fire (e.g. a timer IRQ)?

>> under the new scheme of being processed in the vCPU loop we should only
>> fire this one once all execution is done (although you may exit the loop
>> early before icount is exhausted).
>
> We should stop the vCPU before processing virtual timers because:
> - virtual clock depends on instruction counter
> - virtual timers may change virtual hardware state

If we do the processing in the top of main vCPU loop this should be
equivalent. The instruction counter cannot run because we haven't
entered tcg_exec_cpu. We also process virtual timers in this thread
outside the loop so nothing else can be poking the hardware state.

>> > - replay puts back unexecuted instructions (qemu_icount -= counter)
>> >
>> > But virtual timer cannot take in account non-executed instructions (counter) and
>> > therefore it reads only qemu_icount, which provides incorrect time.
>> >
>> >> But the timers are all enabled:
>> >>
>> >>   (gdb) qemu timers
>> >>   Processing Realtime timers
>> >>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
>> >>   Processing Virtual timers
>> >>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
>> >>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
>> >>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
>> >>   Processing Host timers
>> >>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
>> >>   Processing Virtual RT timers
>> >>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
>> >
>> > Timers are processed only at checkpoints recorded in the log.
>> > When replay is stuck, probably there is a pending checkpoint in the log
>> > and pending instructions in CPU (because iothread breaks its
>> > synchronization).
>>
>> How does this work for instructions that sleep (like WFI)? The WFI will
>> cause us to exit the loop but I assume we need a "real" timer to trigger
>> a firing of whatever the WFI is waiting for as time according to icount
>> isn't advancing.
>
> This is virtual_rt for. It advances even when vCPU is stopped.

So I'm not seeing this happen:

  process_icount_data: icount not increased 117302332749=>117302332749 RT:-1

I wonder if the advance of virtual_rt has been deadlocked? The -1
suggests its not even setup.

>> >> One area I wanted to look back at was comparing the record trace from
>> >> pre-mttcg-merge to now to see if any information was missing. However
>> >
>> > I usually use in_asm and exec logs and also add some logging at replay checkpoints.
>> >
>> >> the bin file has quite a lot of noise in it from changing fields so I
>> >> was wondering do you have any sort of dumper tool for comparing the
>> >> traces? If not is the format of the trace file specified anywhere?
>> >
>> > Usually you cannot compare two different record/replay logs, because there
>> > is no synchronization of the timers in different recording runs and
>> > therefore you'll get totally different logs.
>>
>> I wasn't looking to have identical traces but I was interested in the
>> patterns in the logs and how they have changed. For example:
>>
>> HEADER: version 0xe02005                                      | HEADER: version 0xe02006
>> 1:EVENT_CP_INIT                                                 1:EVENT_CP_INIT
>> 2:EVENT_CLOCK_HOST 0x14afc6687f1fc738                         | 2:EVENT_CLOCK_HOST
>> 0x14b000644239c8d8
>> 3:EVENT_CLOCK_HOST 0x14afc66c6ac91858                         | 3:EVENT_CLOCK_HOST
>> 0x14b00064423a1310
>> 4:EVENT_CP_RESET no additional data                             4:EVENT_CP_RESET no additional
>> data
>> 5:EVENT_CP_CLOCK_WARP_START no additional data                  5:EVENT_CP_CLOCK_WARP_START no
>> additional data
>> 6:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 6:EVENT_CP_CLOCK_WARP_START no
>> additional data
>> 7:EVENT_CP_CLOCK_WARP_START no additional data                | 7:EVENT_CP_CLOCK_VIRTUAL no
>> additional data
>> 8:EVENT_CP_CLOCK_VIRTUAL no additional data                   | 8:EVENT_CP_CLOCK_WARP_ACCOUNT
>> no additional data
>> 9:EVENT_CP_CLOCK_WARP_START no additional data                | 9:EVENT_CP_CLOCK_WARP_ACCOUNT
>> no additional data
>> 10:EVENT_CP_CLOCK_VIRTUAL no additional data                  | 10:EVENT_INSTRUCTION 0x1000000
>> 11:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data               11:EVENT_CP_CLOCK_WARP_ACCOUNT
>> no additional data
>> 12:EVENT_CP_CLOCK_WARP_ACCOUNT no additional data             | 12:EVENT_INSTRUCTION 0x1000000
>> 13:EVENT_INSTRUCTION 0x1000000                                | 13:EVENT_CP_CLOCK_WARP_ACCOUNT
>> no additional data
>>
>> There is a difference to the pattern at the start as the initial
>> checkpoints are layed down. I guess this is due to the interaction of
>> the main thread with the vCPU as they bounce the BQL with each other.
>
> Yes, this may be caused by changed interaction between the threads.
>
>> I'm wondering why we don't just do all the warp timer management in the
>> vCPU thread as well?
>
> Because vCPU may sleep and we'll have to setup some timer (virtual_rt
> as now) anyway.

Right - because if we end up qemu_tcg_wait_io_event(cpu ? cpu :
QTAILQ_FIRST(&cpus)); we need another thread to kick us out of the
qemu_cond_wait(cpu->halt_cond, &qemu_global_mutex);

> By the way, I made small description of the replay log format
> to be later included into docs/replay.txt:
>
> Record/replay log consits of the header and the sequence of execution
> events. The header includes 4-byte replay version id and 8-byte reserved
> field. Version is updated every time replay log format changes to prevent
> using replay log created by another build of qemu.
>
> The sequence of the events describes virtual machine state changes.
> It includes all non-deterministic inputs of VM, synchronization marks and
> instruction counts used to correctly inject inputs at replay.
>
> Synchronization marks (checkpoints) are used for synchronizing qemu threads
> that perform operations with virtual hardware. These operations may change
> system's state (e.g., change some register or generate interrupt) and
> therefore should execute synchronously with CPU thread.
>
> Every event in the log includes 1-byte event id and optional arguments.
> When argument is an array, it is stored as 4-byte array length
> and corresponding number of bytes with data.
> Here is the list of events that are written into the log:
>
>  - EVENT_INSTRUCTION. Instructions executed since last event.
>    Argument: 4-byte number of executed instructions.
>  - EVENT_INTERRUPT. Used to synchronize interrupt processing.
>  - EVENT_EXCEPTION. Used to synchronize exception handling.
>  - EVENT_ASYNC. This is a group of events. They are always processed
>    together with checkpoints. When such an event is generated, it is
>    stored in the queue and processed only when checkpoint occurs.
>    Every such event is followed by 1-byte checkpoint id and 1-byte
>    async event id from the following list:
>      - REPLAY_ASYNC_EVENT_BH. Bottom-half callback. This event synchronizes
>        callbacks that affect virtual machine state, but normally called
>        asyncronously.
>        Argument: 8-byte operation id.
>      - REPLAY_ASYNC_EVENT_INPUT. Input device event. Contains
>        parameters of keyboard and mouse input operations
>        (key press/release, mouse pointer movement).
>        Arguments: 9-16 bytes depending of input event.
>      - REPLAY_ASYNC_EVENT_INPUT_SYNC. Internal input synchronization event.
>      - REPLAY_ASYNC_EVENT_CHAR_READ. Character (e.g., serial port) device input
>        initiated by the sender.
>        Arguments: 1-byte character device id.
>                   Array with bytes were read.
>      - REPLAY_ASYNC_EVENT_BLOCK. Block device operation. Used to synchronize
>        operations with disk and flash drives with CPU.
>        Argument: 8-byte operation id.
>      - REPLAY_ASYNC_EVENT_NET. Incoming network packet.
>        Arguments: 1-byte network adapter id.
>                   4-byte packet flags.
>                   Array with packet bytes.
>  - EVENT_SHUTDOWN. Occurs when user sends shutdown event to qemu,
>    e.g., by closing the window.
>  - EVENT_CHAR_WRITE. Used to synchronize character output operations.
>    Arguments: 4-byte output function return value.
>               4-byte offset in the output array.
>  - EVENT_CHAR_READ_ALL. Used to synchronize character input operations,
>    initiated by qemu.
>    Argument: Array with bytes that were read.
>  - EVENT_CHAR_READ_ALL_ERROR. Unsuccessful character input operation,
>    initiated by qemu.
>    Argument: 4-byte error code.
>  - EVENT_CLOCK + clock_id. Group of events for host clock read operations.
>    Argument: 8-byte clock value.
>  - EVENT_CHECKPOINT + checkpoint_id. Checkpoint for synchronization of
>    CPU, internal threads, and asynchronous input events. May be followed
>    by one or more EVENT_ASYNC events.
>  - EVENT_END. Last event in the log.

Thanks. That's really useful.

Do you think it would be worth including the dumper script I wrote in
./scripts/? I mainly wrote it to aid my understanding of the code flow
but it might be useful in future investigations?

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Pavel Dovgalyuk]

> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
> request@listserver.greensocs.com]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
> >> request@listserver.greensocs.com]
> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> <snip>
> >> >> > I tested on vexpress-a9 platform with Debian wheezy.
> >> >>
> >> >> Thanks for that. I now have a test case that I can reproduce failures on
> >> >> without needing graphics.
> >> >>
> >> >> I've been investigating if there are any problems with the timer
> >> >> processing now they have been moved into the TCG thread. The record
> >> >> stage seems to work fine but I'm having difficulty figuring out why
> >> >> playback freezes. It seems we get to a point where we are stuck waiting
> >> >> for a suspiciously exact timer deadline:
> >> >
> >> > I've encountered the following behavior at replay stage:
> >> > - replay takes some instructions to execute (qemu_icount += counter)
> >> > - virtual timer is fired
> >>
> >> This is the virtual timer based on icount not the virtual rt timer? So
> >
> > Regular virtual timer. It's value is based on icount.
> > virtual_rt is used for internal icount purposes.
> 
> And this is where the clock warps come in? The bias brings the
> virtual_rt time forward because execution is waiting for some external
> event to fire (e.g. a timer IRQ)?

I guess so. But bias is not updated when the vCPU works.
vCPU thread updates only qemu_icount which is used for virtual clock calculation.

> >> under the new scheme of being processed in the vCPU loop we should only
> >> fire this one once all execution is done (although you may exit the loop
> >> early before icount is exhausted).
> >
> > We should stop the vCPU before processing virtual timers because:
> > - virtual clock depends on instruction counter
> > - virtual timers may change virtual hardware state
> 
> If we do the processing in the top of main vCPU loop this should be
> equivalent. The instruction counter cannot run because we haven't
> entered tcg_exec_cpu. We also process virtual timers in this thread
> outside the loop so nothing else can be poking the hardware state.

This is how qemu worked in older version - it switched between
processing tasks (vCPU and timers) in one thread.
But how we'll join this behavior with the current design and MTTCG?

> 
> >> > - replay puts back unexecuted instructions (qemu_icount -= counter)
> >> >
> >> > But virtual timer cannot take in account non-executed instructions (counter) and
> >> > therefore it reads only qemu_icount, which provides incorrect time.
> >> >
> >> >> But the timers are all enabled:
> >> >>
> >> >>   (gdb) qemu timers
> >> >>   Processing Realtime timers
> >> >>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
> >> >>   Processing Virtual timers
> >> >>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
> >> >>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
> >> >>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
> >> >>   Processing Host timers
> >> >>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
> >> >>   Processing Virtual RT timers
> >> >>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
> >> >
> >> > Timers are processed only at checkpoints recorded in the log.
> >> > When replay is stuck, probably there is a pending checkpoint in the log
> >> > and pending instructions in CPU (because iothread breaks its
> >> > synchronization).
> >>
> >> How does this work for instructions that sleep (like WFI)? The WFI will
> >> cause us to exit the loop but I assume we need a "real" timer to trigger
> >> a firing of whatever the WFI is waiting for as time according to icount
> >> isn't advancing.
> >
> > This is virtual_rt for. It advances even when vCPU is stopped.
> 
> So I'm not seeing this happen:
> 
>   process_icount_data: icount not increased 117302332749=>117302332749 RT:-1
> 
> I wonder if the advance of virtual_rt has been deadlocked? The -1
> suggests its not even setup.

qemu_start_warp_timer says that it is setup only when there are active virtual timers.


> > By the way, I made small description of the replay log format
> > to be later included into docs/replay.txt:
> >
> Thanks. That's really useful.
> 
> Do you think it would be worth including the dumper script I wrote in
> ./scripts/? I mainly wrote it to aid my understanding of the code flow
> but it might be useful in future investigations?

Usually I get human-readable logs in record and replay modes to find
divergence between them, but I think your script might be useful in some cases.

Pavel Dovgalyuk

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Paolo Bonzini]

On 31/03/2017 11:16, Pavel Dovgalyuk wrote:
> 
> Do you think it would be worth including the dumper script I wrote in
> ./scripts/? I mainly wrote it to aid my understanding of the code flow
> but it might be useful in future investigations?

Yes, I think it is.  Alternatively, adding "-d rr" that dumps what is
recorded/replayed from the rr file would be useful.

Paolo

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>> request@listserver.greensocs.com]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>> >> request@listserver.greensocs.com]
>> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> <snip>
>> >> >> > I tested on vexpress-a9 platform with Debian wheezy.
>> >> >>
>> >> >> Thanks for that. I now have a test case that I can reproduce failures on
>> >> >> without needing graphics.
>> >> >>
>> >> >> I've been investigating if there are any problems with the timer
>> >> >> processing now they have been moved into the TCG thread. The record
>> >> >> stage seems to work fine but I'm having difficulty figuring out why
>> >> >> playback freezes. It seems we get to a point where we are stuck waiting
>> >> >> for a suspiciously exact timer deadline:
>> >> >
>> >> > I've encountered the following behavior at replay stage:
>> >> > - replay takes some instructions to execute (qemu_icount += counter)
>> >> > - virtual timer is fired
>> >>
>> >> This is the virtual timer based on icount not the virtual rt timer? So
>> >
>> > Regular virtual timer. It's value is based on icount.
>> > virtual_rt is used for internal icount purposes.
>>
>> And this is where the clock warps come in? The bias brings the
>> virtual_rt time forward because execution is waiting for some external
>> event to fire (e.g. a timer IRQ)?
>
> I guess so. But bias is not updated when the vCPU works.
> vCPU thread updates only qemu_icount which is used for virtual clock calculation.
>
>> >> under the new scheme of being processed in the vCPU loop we should only
>> >> fire this one once all execution is done (although you may exit the loop
>> >> early before icount is exhausted).
>> >
>> > We should stop the vCPU before processing virtual timers because:
>> > - virtual clock depends on instruction counter
>> > - virtual timers may change virtual hardware state
>>
>> If we do the processing in the top of main vCPU loop this should be
>> equivalent. The instruction counter cannot run because we haven't
>> entered tcg_exec_cpu. We also process virtual timers in this thread
>> outside the loop so nothing else can be poking the hardware state.
>
> This is how qemu worked in older version - it switched between
> processing tasks (vCPU and timers) in one thread.

The only real difference is the sequencing in the old case was protected
by the BQL - now its my program order.

> But how we'll join this behavior with the current design and MTTCG?

Ignore MTTCG for now. We don't even try and run multiple-threads when
icount is enabled. However the change in the BQL locking is what has
triggered the failures.

Anyway I think I'm getting closer to narrowing it down. On record I see
replay_current_step jump backwards with this:

/* A common event print, called when reading or saving an event */
static void print_event(uint8_t event)
{
    static int event_count;
    static uint64_t last_step;
    uint64_t this_step = replay_get_current_step();

    fprintf(stderr, "replay: event %d is %d @ step=%#" PRIx64 "\n",
            event_count, event, this_step);

    if (this_step < last_step) {
        fprintf(stderr,"%s: !!! step %d went backwards %#"PRIx64"=>%#"PRIx64"!!!\n",
                __func__, event_count, last_step, this_step);
        abort();
    }
    last_step = this_step;
    event_count++;
}

void replay_put_event(uint8_t event)
{
    assert(event < EVENT_COUNT);
    replay_put_byte(event);
    print_event(event);
}

The jump back is fairly consistent in my case (event 66 in the vexpress
run) but I'm fairly sure that is the bug. I can't see any reason for the
step count to go backwards - indeed that breaks the premise of .

Unfortunately when I start putting break and watchpoints in to see how
this jump back occurs the problem goes away until I disable them. So
this very much looks like a race condition corrupting the icount data.

>> >> > - replay puts back unexecuted instructions (qemu_icount -= counter)
>> >> >
>> >> > But virtual timer cannot take in account non-executed instructions (counter) and
>> >> > therefore it reads only qemu_icount, which provides incorrect time.
>> >> >
>> >> >> But the timers are all enabled:
>> >> >>
>> >> >>   (gdb) qemu timers
>> >> >>   Processing Realtime timers
>> >> >>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
>> >> >>   Processing Virtual timers
>> >> >>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
>> >> >>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
>> >> >>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
>> >> >>   Processing Host timers
>> >> >>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
>> >> >>   Processing Virtual RT timers
>> >> >>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
>> >> >
>> >> > Timers are processed only at checkpoints recorded in the log.
>> >> > When replay is stuck, probably there is a pending checkpoint in the log
>> >> > and pending instructions in CPU (because iothread breaks its
>> >> > synchronization).
>> >>
>> >> How does this work for instructions that sleep (like WFI)? The WFI will
>> >> cause us to exit the loop but I assume we need a "real" timer to trigger
>> >> a firing of whatever the WFI is waiting for as time according to icount
>> >> isn't advancing.
>> >
>> > This is virtual_rt for. It advances even when vCPU is stopped.
>>
>> So I'm not seeing this happen:
>>
>>   process_icount_data: icount not increased 117302332749=>117302332749 RT:-1
>>
>> I wonder if the advance of virtual_rt has been deadlocked? The -1
>> suggests its not even setup.
>
> qemu_start_warp_timer says that it is setup only when there are active virtual timers.
>
>
>> > By the way, I made small description of the replay log format
>> > to be later included into docs/replay.txt:
>> >
>> Thanks. That's really useful.
>>
>> Do you think it would be worth including the dumper script I wrote in
>> ./scripts/? I mainly wrote it to aid my understanding of the code flow
>> but it might be useful in future investigations?
>
> Usually I get human-readable logs in record and replay modes to find
> divergence between them, but I think your script might be useful in some cases.

Cool. I'll include it in the icount series once I have something to post
(fingers crossed I'm getting close).

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Paolo Bonzini]

On 31/03/2017 13:21, Alex Bennée wrote:
> Anyway I think I'm getting closer to narrowing it down. On record I see
> replay_current_step jump backwards with this:
> 
> /* A common event print, called when reading or saving an event */
> static void print_event(uint8_t event)
> {
>     static int event_count;
>     static uint64_t last_step;
>     uint64_t this_step = replay_get_current_step();
> 
>     fprintf(stderr, "replay: event %d is %d @ step=%#" PRIx64 "\n",
>             event_count, event, this_step);
> 
>     if (this_step < last_step) {
>         fprintf(stderr,"%s: !!! step %d went backwards %#"PRIx64"=>%#"PRIx64"!!!\n",
>                 __func__, event_count, last_step, this_step);
>         abort();
>     }
>     last_step = this_step;
>     event_count++;
> }
> 
> void replay_put_event(uint8_t event)
> {
>     assert(event < EVENT_COUNT);
>     replay_put_byte(event);
>     print_event(event);
> }
> 
> The jump back is fairly consistent in my case (event 66 in the vexpress
> run) but I'm fairly sure that is the bug. I can't see any reason for the
> step count to go backwards - indeed that breaks the premise of .

Good catch!  I suspect it's the "else" case in cpu_get_icount_raw:

    icount = timers_state.qemu_icount;
    if (cpu) {
        if (!cpu->can_do_io) {
            fprintf(stderr, "Bad icount read\n");
            exit(1);
        }
        icount -= (cpu->icount_decr.u16.low + cpu->icount_extra);
    }

Between

        timers_state.qemu_icount += count;

and

        timers_state.qemu_icount -= (cpu->icount_decr.u16.low
                                    + cpu->icount_extra);

the I/O thread can read a value that is later rolled back.  I think you
need to do this the other way round: add something to icount in
cpu_get_icount_raw rather than taking it off:

    icount = timers_state.qemu_icount;
    if (cpu) {
        if (!cpu->can_do_io) {
            fprintf(stderr, "Bad icount read\n");
            exit(1);
        }
        icount += cpu->pending_icount
            - (cpu->icount_decr.u16.low + cpu->icount_extra);
    }

where cpu->pending_icount is set before cpu_exec, and folded into
timers_state.qemu_icount afterwards.

Also, here:

    if (use_icount) {
        int64_t count;
        int decr;
        timers_state.qemu_icount -= (cpu->icount_decr.u16.low
                                    + cpu->icount_extra);
        cpu->icount_decr.u16.low = 0;
        cpu->icount_extra = 0;

this should be dead code because tcg_cpu_exec also clears the two
decrementer fields.  So if you can replace the three assignments with
assertions on cpu->icount_decr.u16.low and cpu->icount_extra, that would
also simplify the code and remove race opportunities.

Paolo

>>>>>> - replay puts back unexecuted instructions (qemu_icount -= counter)
>>>>>>
>>>>>> But virtual timer cannot take in account non-executed instructions (counter) and
>>>>>> therefore it reads only qemu_icount, which provides incorrect time.
>>>>>>
>>>>>>> But the timers are all enabled:
>>>>>>>
>>>>>>>   (gdb) qemu timers
>>>>>>>   Processing Realtime timers
>>>>>>>     clock QEMU_CLOCK_REALTIME is enabled:true, last:-9223372036854775808
>>>>>>>   Processing Virtual timers
>>>>>>>     clock QEMU_CLOCK_VIRTUAL is enabled:true, last:-9223372036854775808
>>>>>>>       timer 34297350016/1 (cb:0x555555a2e952 <ptimer_tick>)
>>>>>>>       timer 503290000000/1000000 (cb:0x555555bd4d1d <ra_timer_handler>)
>>>>>>>   Processing Host timers
>>>>>>>     clock QEMU_CLOCK_HOST is enabled:true, last:1490191319270134000
>>>>>>>   Processing Virtual RT timers
>>>>>>>     clock QEMU_CLOCK_VIRTUAL_RT is enabled:true, last:-9223372036854775808
>>>>>>
>>>>>> Timers are processed only at checkpoints recorded in the log.
>>>>>> When replay is stuck, probably there is a pending checkpoint in the log
>>>>>> and pending instructions in CPU (because iothread breaks its
>>>>>> synchronization).
>>>>>
>>>>> How does this work for instructions that sleep (like WFI)? The WFI will
>>>>> cause us to exit the loop but I assume we need a "real" timer to trigger
>>>>> a firing of whatever the WFI is waiting for as time according to icount
>>>>> isn't advancing.
>>>>
>>>> This is virtual_rt for. It advances even when vCPU is stopped.
>>>
>>> So I'm not seeing this happen:
>>>
>>>   process_icount_data: icount not increased 117302332749=>117302332749 RT:-1
>>>
>>> I wonder if the advance of virtual_rt has been deadlocked? The -1
>>> suggests its not even setup.
>>
>> qemu_start_warp_timer says that it is setup only when there are active virtual timers.
>>
>>
>>>> By the way, I made small description of the replay log format
>>>> to be later included into docs/replay.txt:
>>>>
>>> Thanks. That's really useful.
>>>
>>> Do you think it would be worth including the dumper script I wrote in
>>> ./scripts/? I mainly wrote it to aid my understanding of the code flow
>>> but it might be useful in future investigations?
>>
>> Usually I get human-readable logs in record and replay modes to find
>> divergence between them, but I think your script might be useful in some cases.
> 
> Cool. I'll include it in the icount series once I have something to post
> (fingers crossed I'm getting close).
> 
> --
> Alex Bennée
> 

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Paolo Bonzini <pbonzini@redhat.com> writes:

> On 31/03/2017 13:21, Alex Bennée wrote:
>> Anyway I think I'm getting closer to narrowing it down. On record I see
>> replay_current_step jump backwards with this:
>>
>> /* A common event print, called when reading or saving an event */
>> static void print_event(uint8_t event)
>> {
>>     static int event_count;
>>     static uint64_t last_step;
>>     uint64_t this_step = replay_get_current_step();
>>
>>     fprintf(stderr, "replay: event %d is %d @ step=%#" PRIx64 "\n",
>>             event_count, event, this_step);
>>
>>     if (this_step < last_step) {
>>         fprintf(stderr,"%s: !!! step %d went backwards %#"PRIx64"=>%#"PRIx64"!!!\n",
>>                 __func__, event_count, last_step, this_step);
>>         abort();
>>     }
>>     last_step = this_step;
>>     event_count++;
>> }
>>
>> void replay_put_event(uint8_t event)
>> {
>>     assert(event < EVENT_COUNT);
>>     replay_put_byte(event);
>>     print_event(event);
>> }
>>
>> The jump back is fairly consistent in my case (event 66 in the vexpress
>> run) but I'm fairly sure that is the bug. I can't see any reason for the
>> step count to go backwards - indeed that breaks the premise of .
>
> Good catch!  I suspect it's the "else" case in cpu_get_icount_raw:
>
>     icount = timers_state.qemu_icount;
>     if (cpu) {
>         if (!cpu->can_do_io) {
>             fprintf(stderr, "Bad icount read\n");
>             exit(1);
>         }
>         icount -= (cpu->icount_decr.u16.low + cpu->icount_extra);
>     }
>
> Between
>
>         timers_state.qemu_icount += count;
>
> and
>
>         timers_state.qemu_icount -= (cpu->icount_decr.u16.low
>                                     + cpu->icount_extra);
>
> the I/O thread can read a value that is later rolled back.  I think you
> need to do this the other way round: add something to icount in
> cpu_get_icount_raw rather than taking it off:
>
>     icount = timers_state.qemu_icount;
>     if (cpu) {
>         if (!cpu->can_do_io) {
>             fprintf(stderr, "Bad icount read\n");
>             exit(1);
>         }
>         icount += cpu->pending_icount
>             - (cpu->icount_decr.u16.low + cpu->icount_extra);
>     }
>
> where cpu->pending_icount is set before cpu_exec, and folded into
> timers_state.qemu_icount afterwards.
>
> Also, here:
>
>     if (use_icount) {
>         int64_t count;
>         int decr;
>         timers_state.qemu_icount -= (cpu->icount_decr.u16.low
>                                     + cpu->icount_extra);
>         cpu->icount_decr.u16.low = 0;
>         cpu->icount_extra = 0;
>
> this should be dead code because tcg_cpu_exec also clears the two
> decrementer fields.  So if you can replace the three assignments with
> assertions on cpu->icount_decr.u16.low and cpu->icount_extra, that would
> also simplify the code and remove race opportunities.

I'll have a look at that on Monday. I wrote this before I saw your
email:

  https://github.com/stsquad/qemu/tree/mttcg/debug-record-replay-v1

It fixes the race so time only ever goes forward. Combined with the
following patches it also makes the record/replay streams tolerant of
"missing the boat". With this I can do a initrd run of the vexpress
kernel in both record and playback.

I'm not sure it counts as deterministic though - the vCPU and main-loop
thread seem to figure it out as the go along but I suspect if we really
want to be sure we push the replay_lock() further up. This would ensure
all related events from whichever thread are pushed together.

This is very much a come back on Monday and see if it still seems like a
good idea in the cold light of morning ;-)

--
Alex Bennée

Re: [Qemu-devel] [PATCH v3 00/11] MTTCG fix-ups for 2.9

[Alex Bennée]

Alex Bennée <alex.bennee@linaro.org> writes:

> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>
>>> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-request@listserver.greensocs.com]
>>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>>> request@listserver.greensocs.com]
>>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>> >> >> From: mttcg-request@listserver.greensocs.com [mailto:mttcg-
>>> >> request@listserver.greensocs.com]
>>> >> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>> <snip>
>>> >> >> > I tested on vexpress-a9 platform with Debian wheezy.
>>> >> >>
>>> >> >> Thanks for that. I now have a test case that I can reproduce failures on
>>> >> >> without needing graphics.
>>> >> >>
>>> >> >> I've been investigating if there are any problems with the timer
>>> >> >> processing now they have been moved into the TCG thread. The record
>>> >> >> stage seems to work fine but I'm having difficulty figuring out why
>>> >> >> playback freezes. It seems we get to a point where we are stuck waiting
>>> >> >> for a suspiciously exact timer deadline:
>>> >> >
>>> >> > I've encountered the following behavior at replay stage:
>>> >> > - replay takes some instructions to execute (qemu_icount += counter)
>>> >> > - virtual timer is fired
>>> >>
>>> >> This is the virtual timer based on icount not the virtual rt timer? So
>>> >
>>> > Regular virtual timer. It's value is based on icount.
>>> > virtual_rt is used for internal icount purposes.
>>>
>>> And this is where the clock warps come in? The bias brings the
>>> virtual_rt time forward because execution is waiting for some external
>>> event to fire (e.g. a timer IRQ)?
>>
>> I guess so. But bias is not updated when the vCPU works.
>> vCPU thread updates only qemu_icount which is used for virtual clock calculation.
>>
>>> >> under the new scheme of being processed in the vCPU loop we should only
>>> >> fire this one once all execution is done (although you may exit the loop
>>> >> early before icount is exhausted).
>>> >
>>> > We should stop the vCPU before processing virtual timers because:
>>> > - virtual clock depends on instruction counter
>>> > - virtual timers may change virtual hardware state
>>>
>>> If we do the processing in the top of main vCPU loop this should be
>>> equivalent. The instruction counter cannot run because we haven't
>>> entered tcg_exec_cpu. We also process virtual timers in this thread
>>> outside the loop so nothing else can be poking the hardware state.
>>
>> This is how qemu worked in older version - it switched between
>> processing tasks (vCPU and timers) in one thread.
>
> The only real difference is the sequencing in the old case was protected
> by the BQL - now its my program order.
>
>> But how we'll join this behavior with the current design and MTTCG?
>
> Ignore MTTCG for now. We don't even try and run multiple-threads when
> icount is enabled. However the change in the BQL locking is what has
> triggered the failures.
>
> Anyway I think I'm getting closer to narrowing it down. On record I see
> replay_current_step jump backwards with this:
>
> /* A common event print, called when reading or saving an event */
> static void print_event(uint8_t event)
> {
>     static int event_count;
>     static uint64_t last_step;
>     uint64_t this_step = replay_get_current_step();
>
>     fprintf(stderr, "replay: event %d is %d @ step=%#" PRIx64 "\n",
>             event_count, event, this_step);
>
>     if (this_step < last_step) {
>         fprintf(stderr,"%s: !!! step %d went backwards %#"PRIx64"=>%#"PRIx64"!!!\n",
>                 __func__, event_count, last_step, this_step);
>         abort();
>     }
>     last_step = this_step;
>     event_count++;
> }
>
> void replay_put_event(uint8_t event)
> {
>     assert(event < EVENT_COUNT);
>     replay_put_byte(event);
>     print_event(event);
> }
>
> The jump back is fairly consistent in my case (event 66 in the vexpress
> run) but I'm fairly sure that is the bug. I can't see any reason for the
> step count to go backwards - indeed that breaks the premise of .
>
> Unfortunately when I start putting break and watchpoints in to see how
> this jump back occurs the problem goes away until I disable them. So
> this very much looks like a race condition corrupting the icount data.

So this is a symptom of cpu_get_icount_raw(void) only accounting for in
progress instructions when in the vCPU context and the fact
timers_state.qemu_icount is "in credit" while the vCPU is running.

--
Alex Bennée