Re: [RFC PATCH] tests/functional/s390x: Add reverse debugging test for s390x

[Ilya Leoshkevich <iii@linux.ibm.com>]

On Sun, 2025-11-30 at 20:03 +0100, Ilya Leoshkevich wrote:
> On Sun, 2025-11-30 at 19:32 +0100, Ilya Leoshkevich wrote:
> > On Sun, 2025-11-30 at 16:47 +0000, Alex Bennée wrote:
> > > Ilya Leoshkevich <iii@linux.ibm.com> writes:
> > > 
> > > > On Fri, 2025-11-28 at 18:25 +0100, Ilya Leoshkevich wrote:
> > > > > On Fri, 2025-11-28 at 14:39 +0100, Thomas Huth wrote:
> > > > > > From: Thomas Huth <thuth@redhat.com>
> > > > > > 
> > > > > > We just have to make sure that we can set the endianness to
> > > > > > big
> > > > > > endian,
> > > > > > then we can also run this test on s390x.
> > > > > > 
> > > > > > Signed-off-by: Thomas Huth <thuth@redhat.com>
> > > > > > ---
> > > > > >  Marked as RFC since it depends on the fix for this bug (so
> > > > > > it
> > > > > > cannot
> > > > > >  be merged yet):
> > > > > >  
> > > > > > https://lore.kernel.org/qemu-devel/a0accce9-6042-4a7b-a7c7-218212818891@redhat.com
> > > > > > /
> > > > > > 
> > > > > >  tests/functional/reverse_debugging.py        |  4 +++-
> > > > > >  tests/functional/s390x/meson.build           |  1 +
> > > > > >  tests/functional/s390x/test_reverse_debug.py | 21
> > > > > > ++++++++++++++++++++
> > > > > >  3 files changed, 25 insertions(+), 1 deletion(-)
> > > > > >  create mode 100755
> > > > > > tests/functional/s390x/test_reverse_debug.py
> > > > > 
> > > > > Reviewed-by: Ilya Leoshkevich <iii@linux.ibm.com>
> > > > > 
> > > > > 
> > > > > I have a simple fix which helps with your original report,
> > > > > but
> > > > > not
> > > > > with this test. I'm still investigating.
> > > > > 
> > > > > --- a/target/s390x/machine.c
> > > > > +++ b/target/s390x/machine.c
> > > > > @@ -52,6 +52,14 @@ static int cpu_pre_save(void *opaque)
> > > > >          kvm_s390_vcpu_interrupt_pre_save(cpu);
> > > > >      }
> > > > >  
> > > > > +    if (tcg_enabled()) {
> > > > > +        /*
> > > > > +         * Ensure symmetry with cpu_post_load() with respect
> > > > > to
> > > > > +         * CHECKPOINT_CLOCK_VIRTUAL.
> > > > > +         */
> > > > > +        tcg_s390_tod_updated(CPU(cpu), RUN_ON_CPU_NULL);
> > > > > +    }
> > > > > +
> > > > >      return 0;
> > > > >  }
> > > > 
> > > > Interestingly enough, this patch fails only under load, e.g.,
> > > > if
> > > > I
> > > > run
> > > > make check -j"$(nproc)" or if I run your test in isolation, but
> > > > with
> > > > stress-ng cpu in background. The culprit appears to be:
> > > > 
> > > > s390_tod_load()
> > > >   qemu_s390_tod_set()
> > > >     async_run_on_cpu(tcg_s390_tod_updated)
> > > > 
> > > > Depending on the system load, this additional
> > > > tcg_s390_tod_updated()
> > > > may or may not end up being called during handle_backward(). If
> > > > it
> > > > does, we get an infinite loop again, because now we need two
> > > > checkpoints.
> > > > 
> > > > I have a feeling that this code may be violating some record-
> > > > replay
> > > > requirement, but I can't quite put my finger on it. For
> > > > example,
> > > > async_run_on_cpu() does not sound like something deterministic,
> > > > but
> > > > then again it just queues work for rr_cpu_thread_fn(), which is
> > > > supposed to be deterministic.
> > > 
> > > The the async_run_on_cpu is called from the vcpu thread in
> > > response
> > > to a
> > > deterministic event at a known point in time it should be fine.
> > > If
> > > it
> > > came from another thread that is not synchronised via replay_lock
> > > then
> > > things will go wrong.
> > > 
> > > But this is a VM load save helper?
> > 
> > Yes, and it's called from the main thread. Either during
> > initialization, or as a reaction to GDB packets.
> > 
> > Here is the call stack:
> > 
> >   qemu_loadvm_state()
> >     qemu_loadvm_state_main()
> >       qemu_loadvm_section_start_full()
> >         vmstate_load()
> >           vmstate_load_state()
> >             cpu_post_load()
> >               tcg_s390_tod_updated()
> >                 update_ckc_timer()
> >                   timer_mod()
> >           s390_tod_load()
> >             qemu_s390_tod_set()  # via tdc->set()
> >               async_run_on_cpu(tcg_s390_tod_updated)
> > 
> > So you think we may have to take the replay lock around
> > load_snapshot()? So that all async_run_on_cpu() calls it makes end
> > up
> > being handled by the vCPU thread deterministically.
> 
> To answer my own question: apparently this is already the case; at
> least, the following does not cause any fallout:
> 
> diff --git a/include/system/replay.h b/include/system/replay.h
> index 6859df09580..e1cd9b2f900 100644
> --- a/include/system/replay.h
> +++ b/include/system/replay.h
> @@ -60,6 +60,7 @@ extern char *replay_snapshot;
>  
>  void replay_mutex_lock(void);
>  void replay_mutex_unlock(void);
> +bool replay_mutex_locked(void);
>  
>  static inline void replay_unlock_guard(void *unused)
>  {
> diff --git a/migration/savevm.c b/migration/savevm.c
> index 62cc2ce25cb..ba945d3a1ea 100644
> --- a/migration/savevm.c
> +++ b/migration/savevm.c
> @@ -3199,6 +3199,8 @@ bool save_snapshot(const char *name, bool
> overwrite, const char *vmstate,
>      uint64_t vm_state_size;
>      g_autoptr(GDateTime) now = g_date_time_new_now_local();
>  
> +    g_assert(replay_mutex_locked());
> +
>      GLOBAL_STATE_CODE();
>  
>      if (!migrate_can_snapshot(errp)) {
> @@ -3390,6 +3392,8 @@ bool load_snapshot(const char *name, const char
> *vmstate,
>      int ret;
>      MigrationIncomingState *mis = migration_incoming_get_current();
>  
> +    g_assert(replay_mutex_locked());
> +
>      if (!migrate_can_snapshot(errp)) {
>          return false;
>      }
> diff --git a/replay/replay-internal.h b/replay/replay-internal.h
> index 75249b76936..30825a0753e 100644
> --- a/replay/replay-internal.h
> +++ b/replay/replay-internal.h
> @@ -124,7 +124,6 @@ void replay_get_array_alloc(uint8_t **buf, size_t
> *size);
>   * synchronisation between vCPU and main-loop threads. */
>  
>  void replay_mutex_init(void);
> -bool replay_mutex_locked(void);
>  
>  /*! Checks error status of the file. */
>  void replay_check_error(void);

I believe now I at least understand what the race is about:

- cpu_post_load() fires the TOD timer immediately.

- s390_tod_load() schedules work for firing the TOD timer.

- If rr loop sees work and then timer, we get one timer callback.

- If rr loop sees timer and then work, we get two timer callbacks.

- Record and replay may diverge due to this race.

- In this particular case divergence makes rr loop spin: it sees that
  TOD timer has expired, but cannot invoke its callback, because there
  is no recorded CHECKPOINT_CLOCK_VIRTUAL.

- The order in which rr loop sees work and timer depends on whether
  and when rr loop wakes up during load_snapshot().

- rr loop may wake up after the main thread kicks the CPU and drops
  the BQL, which may happen if it calls, e.g., qemu_cond_wait_bql().