We recently introduced plugin API for the registration of callbacks for
discontinuity events, specifically for interrupts, exceptions and host
call events. The callback receives, among other information, the VCPU
index and the PC after the event. This change introduces a test plugin
asserting that particular behaviour.
---
 tests/tcg/plugins/discons.c   | 95 +++++++++++++++++++++++++++++++++++
 tests/tcg/plugins/meson.build |  2 +-
 2 files changed, 96 insertions(+), 1 deletion(-)
 create mode 100644 tests/tcg/plugins/discons.c

diff --git a/tests/tcg/plugins/discons.c b/tests/tcg/plugins/discons.c
new file mode 100644
index 0000000000..54e52f563a
--- /dev/null
+++ b/tests/tcg/plugins/discons.c
@@ -0,0 +1,95 @@
+/*
+ * Copyright (C) 2024, Julian Ganz <neither@nut.email>
+ *
+ * License: GNU GPL, version 2 or later.
+ *   See the COPYING file in the top-level directory.
+ */
+#include <stdio.h>
+
+#include <qemu-plugin.h>
+
+QEMU_PLUGIN_EXPORT int qemu_plugin_version = QEMU_PLUGIN_VERSION;
+
+struct cpu_state {
+    uint64_t next_pc;
+    bool has_next;
+};
+
+static struct qemu_plugin_scoreboard *states;
+
+static bool abort_on_mismatch;
+
+static void vcpu_discon(qemu_plugin_id_t id, unsigned int vcpu_index,
+                        enum qemu_plugin_discon_type type, uint64_t from_pc,
+                        uint64_t to_pc)
+{
+    struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
+    state->next_pc = to_pc;
+    state->has_next = true;
+}
+
+static void insn_exec(unsigned int vcpu_index, void *userdata)
+{
+    struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
+    uint64_t pc = (uint64_t) userdata;
+    GString* report;
+
+    if (state->has_next) {
+        if (state->next_pc != pc) {
+            report = g_string_new("Trap target PC mismatch\n");
+            g_string_append_printf(report,
+                                   "Expected:    %"PRIx64"\nEncountered: %"
+                                   PRIx64"\n",
+                                   state->next_pc, pc);
+            qemu_plugin_outs(report->str);
+            if (abort_on_mismatch) {
+                g_abort();
+            }
+            g_string_free(report, true);
+        }
+        state->has_next = false;
+    }
+}
+
+static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb)
+{
+    size_t i;
+    size_t n_insns = qemu_plugin_tb_n_insns(tb);
+
+    for (i = 0; i < n_insns; i++) {
+        struct qemu_plugin_insn * insn = qemu_plugin_tb_get_insn(tb, i);
+        uint64_t pc = qemu_plugin_insn_vaddr(insn);
+        qemu_plugin_register_vcpu_insn_exec_cb(insn, insn_exec,
+                                               QEMU_PLUGIN_CB_NO_REGS,
+                                               (void*) pc);
+    }
+}
+
+QEMU_PLUGIN_EXPORT int qemu_plugin_install(qemu_plugin_id_t id,
+                                           const qemu_info_t *info,
+                                           int argc, char **argv)
+{
+    int i;
+
+    for (i = 0; i < argc; i++) {
+        char *opt = argv[i];
+        g_auto(GStrv) tokens = g_strsplit(opt, "=", 2);
+        if (g_strcmp0(tokens[0], "abort") == 0) {
+            if (!qemu_plugin_bool_parse(tokens[0], tokens[1], &abort_on_mismatch)) {
+                fprintf(stderr, "boolean argument parsing failed: %s\n", opt);
+                return -1;
+            }
+        } else {
+            fprintf(stderr, "option parsing failed: %s\n", opt);
+            return -1;
+        }
+    }
+
+    states = qemu_plugin_scoreboard_new(sizeof(struct cpu_state));
+
+    qemu_plugin_register_vcpu_discon_cb(id, QEMU_PLUGIN_DISCON_ALL,
+                                        vcpu_discon);
+    qemu_plugin_register_vcpu_tb_trans_cb(id, vcpu_tb_trans);
+
+    return 0;
+}
diff --git a/tests/tcg/plugins/meson.build b/tests/tcg/plugins/meson.build
index f847849b1b..f057238da1 100644
--- a/tests/tcg/plugins/meson.build
+++ b/tests/tcg/plugins/meson.build
@@ -1,6 +1,6 @@
 t = []
 if get_option('plugins')
-  foreach i : ['bb', 'empty', 'inline', 'insn', 'mem', 'syscall']
+  foreach i : ['bb', 'discons', 'empty', 'inline', 'insn', 'mem', 'syscall']
     if host_os == 'windows'
       t += shared_module(i, files(i + '.c') + '../../../contrib/plugins/win32_linker.c',
                         include_directories: '../../../include/qemu',
-- 
2.45.2

On 12/2/24 11:41, Julian Ganz wrote:
> We recently introduced plugin API for the registration of callbacks for
> discontinuity events, specifically for interrupts, exceptions and host
> call events. The callback receives, among other information, the VCPU
> index and the PC after the event. This change introduces a test plugin
> asserting that particular behaviour.
> ---
>   tests/tcg/plugins/discons.c   | 95 +++++++++++++++++++++++++++++++++++
>   tests/tcg/plugins/meson.build |  2 +-
>   2 files changed, 96 insertions(+), 1 deletion(-)
>   create mode 100644 tests/tcg/plugins/discons.c
> 
> diff --git a/tests/tcg/plugins/discons.c b/tests/tcg/plugins/discons.c
> new file mode 100644
> index 0000000000..54e52f563a
> --- /dev/null
> +++ b/tests/tcg/plugins/discons.c
> @@ -0,0 +1,95 @@
> +/*
> + * Copyright (C) 2024, Julian Ganz <neither@nut.email>
> + *
> + * License: GNU GPL, version 2 or later.
> + *   See the COPYING file in the top-level directory.
> + */

Would be nice to include a description of the plugin here.

> +#include <stdio.h>
> +
> +#include <qemu-plugin.h>
> +
> +QEMU_PLUGIN_EXPORT int qemu_plugin_version = QEMU_PLUGIN_VERSION;
> +
> +struct cpu_state {
> +    uint64_t next_pc;
> +    bool has_next;
> +};
> +
> +static struct qemu_plugin_scoreboard *states;
> +
> +static bool abort_on_mismatch;
> +
> +static void vcpu_discon(qemu_plugin_id_t id, unsigned int vcpu_index,
> +                        enum qemu_plugin_discon_type type, uint64_t from_pc,
> +                        uint64_t to_pc)
> +{
> +    struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
> +    state->next_pc = to_pc;
> +    state->has_next = true;
> +}
> +
> +static void insn_exec(unsigned int vcpu_index, void *userdata)
> +{
> +    struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
> +    uint64_t pc = (uint64_t) userdata;
> +    GString* report;
> +
> +    if (state->has_next) {
> +        if (state->next_pc != pc) {
> +            report = g_string_new("Trap target PC mismatch\n");
> +            g_string_append_printf(report,
> +                                   "Expected:    %"PRIx64"\nEncountered: %"
> +                                   PRIx64"\n",
> +                                   state->next_pc, pc);
> +            qemu_plugin_outs(report->str);
> +            if (abort_on_mismatch) {
> +                g_abort();
> +            }
> +            g_string_free(report, true);
> +        }
> +        state->has_next = false;
> +    }
> +}

When booting an arm64 vm, I get this message:
Trap target PC mismatch
Expected:    23faf3a80
Encountered: 23faf3a84

 From what I understand, it means that the next_pc we have is incorrect.

> +
> +static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb)
> +{
> +    size_t i;
> +    size_t n_insns = qemu_plugin_tb_n_insns(tb);
> +
> +    for (i = 0; i < n_insns; i++) {
> +        struct qemu_plugin_insn * insn = qemu_plugin_tb_get_insn(tb, i);
> +        uint64_t pc = qemu_plugin_insn_vaddr(insn);
> +        qemu_plugin_register_vcpu_insn_exec_cb(insn, insn_exec,
> +                                               QEMU_PLUGIN_CB_NO_REGS,
> +                                               (void*) pc);
> +    }
 > +}> +
> +QEMU_PLUGIN_EXPORT int qemu_plugin_install(qemu_plugin_id_t id,
> +                                           const qemu_info_t *info,
> +                                           int argc, char **argv)
> +{
> +    int i;
> +
> +    for (i = 0; i < argc; i++) {
> +        char *opt = argv[i];
> +        g_auto(GStrv) tokens = g_strsplit(opt, "=", 2);
> +        if (g_strcmp0(tokens[0], "abort") == 0) {
> +            if (!qemu_plugin_bool_parse(tokens[0], tokens[1], &abort_on_mismatch)) {
> +                fprintf(stderr, "boolean argument parsing failed: %s\n", opt);
> +                return -1;
> +            }
> +        } else {
> +            fprintf(stderr, "option parsing failed: %s\n", opt);
> +            return -1;
> +        }
> +    }
> +
> +    states = qemu_plugin_scoreboard_new(sizeof(struct cpu_state));
> +
> +    qemu_plugin_register_vcpu_discon_cb(id, QEMU_PLUGIN_DISCON_ALL,
> +                                        vcpu_discon);
> +    qemu_plugin_register_vcpu_tb_trans_cb(id, vcpu_tb_trans);
> +
> +    return 0;
> +}
> diff --git a/tests/tcg/plugins/meson.build b/tests/tcg/plugins/meson.build
> index f847849b1b..f057238da1 100644
> --- a/tests/tcg/plugins/meson.build
> +++ b/tests/tcg/plugins/meson.build
> @@ -1,6 +1,6 @@
>   t = []
>   if get_option('plugins')
> -  foreach i : ['bb', 'empty', 'inline', 'insn', 'mem', 'syscall']
> +  foreach i : ['bb', 'discons', 'empty', 'inline', 'insn', 'mem', 'syscall']
>       if host_os == 'windows'
>         t += shared_module(i, files(i + '.c') + '../../../contrib/plugins/win32_linker.c',
>                           include_directories: '../../../include/qemu',

Hi Pierrick,

December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
> On 12/2/24 11:41, Julian Ganz wrote:
> >  +static void insn_exec(unsigned int vcpu_index, void *userdata)
> >  +{
> >  + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
> >  + uint64_t pc = (uint64_t) userdata;
> >  + GString* report;
> >  +
> >  + if (state->has_next) {
> >  + if (state->next_pc != pc) {
> >  + report = g_string_new("Trap target PC mismatch\n");
> >  + g_string_append_printf(report,
> >  + "Expected: %"PRIx64"\nEncountered: %"
> >  + PRIx64"\n",
> >  + state->next_pc, pc);
> >  + qemu_plugin_outs(report->str);
> >  + if (abort_on_mismatch) {
> >  + g_abort();
> >  + }
> >  + g_string_free(report, true);
> >  + }
> >  + state->has_next = false;
> >  + }
> >  +}
> > 
> When booting an arm64 vm, I get this message:
> Trap target PC mismatch
> Expected: 23faf3a80
> Encountered: 23faf3a84

A colleague of mine went to great lengths trying to track and reliably
reproduce this. We think that it's something amiss with the existing
instruction exec callback infrastructure. So... it's not something I'll
be addressing with the next iteration as it's out of scope. We'll
probably continue looking into it, though.

The mismatch is reported perfectly normal and boring exceptions and
interrupts with no indication of any differences to other (not reported)
events that fire on a regular basis. Apparently, once in a blue moon
(relatively speaking), for the first instruction of a handler (even
though it is definitely executed and qemu does print a trace-line for
that instruction):

| Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
| Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
| Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
| Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
| Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
| Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
| Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
| Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
| cpu_io_recompile: rewound execution of TB to 000000023fde7b90
| Taking exception 5 [IRQ] on CPU 0
| ...from EL1 to EL1
| ...with ESR 0x0/0x3800000
| ...with SPSR 0x20000305
| ...with ELR 0x23fde7b90
| ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
| Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
| Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
| Trap target PC mismatch CPU 0
| Expected:    23fd77a80
| Encountered: 23fd77a84
| warning: 44	./nptl/pthread_kill.c: No such file or directory
| Couldn't get registers: No such process.

It does show up with both single-core and multi-core VMs, so that at
least eliminates some possibilities. Maybe :/

The issue is nasty to reproduce in a way that allows any meaningful
investigation. It usually involves sifting through many GBs of Qemu logs
for maybe one occurance. We could add another testing/dummy plugin that
just prints the PC for _any_ instruction executed and have a skript
check for non-alternating Trace-lines from Qemu and that Plugin. But
then we're talking nearly double the amount of Lines to look through
with probably little additional information.

Regards,
Julian

"Julian Ganz" <neither@nut.email> writes:

(Add Richard to CC)

> Hi Pierrick,
>
> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>> On 12/2/24 11:41, Julian Ganz wrote:
>> >  +static void insn_exec(unsigned int vcpu_index, void *userdata)
>> >  +{
>> >  + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
>> >  + uint64_t pc = (uint64_t) userdata;
>> >  + GString* report;
>> >  +
>> >  + if (state->has_next) {
>> >  + if (state->next_pc != pc) {
>> >  + report = g_string_new("Trap target PC mismatch\n");
>> >  + g_string_append_printf(report,
>> >  + "Expected: %"PRIx64"\nEncountered: %"
>> >  + PRIx64"\n",
>> >  + state->next_pc, pc);
>> >  + qemu_plugin_outs(report->str);
>> >  + if (abort_on_mismatch) {
>> >  + g_abort();
>> >  + }
>> >  + g_string_free(report, true);
>> >  + }
>> >  + state->has_next = false;
>> >  + }
>> >  +}
>> > 
>> When booting an arm64 vm, I get this message:
>> Trap target PC mismatch
>> Expected: 23faf3a80
>> Encountered: 23faf3a84
>
> A colleague of mine went to great lengths trying to track and reliably
> reproduce this. We think that it's something amiss with the existing
> instruction exec callback infrastructure. So... it's not something I'll
> be addressing with the next iteration as it's out of scope. We'll
> probably continue looking into it, though.
>
> The mismatch is reported perfectly normal and boring exceptions and
> interrupts with no indication of any differences to other (not reported)
> events that fire on a regular basis. Apparently, once in a blue moon
> (relatively speaking), for the first instruction of a handler (even
> though it is definitely executed and qemu does print a trace-line for
> that instruction):
>
> | Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
> | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
> | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
> | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
> | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
> | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
> | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
> | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
> | cpu_io_recompile: rewound execution of TB to 000000023fde7b90

So this happens when an instruction that is not the last instruction of
the block does some IO. As IO accesses can potentially change system
state we can't allow more instructions to run in the block that might
not have that change of state captured

cpu_io_recompile exits the loop and forces the next TranslationBlock to
be only one (or maybe two instructions). We have to play games with
instrumentation to avoid double counting execution:

    /*
     * Exit the loop and potentially generate a new TB executing the
     * just the I/O insns. We also limit instrumentation to memory
     * operations only (which execute after completion) so we don't
     * double instrument the instruction.
     */
    cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | n;

The instruction is in a weird state having both executed (from the
plugin point of view) but not changed any state (stopped from doing MMIO
until the next instruction).

> | Taking exception 5 [IRQ] on CPU 0
> | ...from EL1 to EL1
> | ...with ESR 0x0/0x3800000
> | ...with SPSR 0x20000305
> | ...with ELR 0x23fde7b90
> | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5

I guess before we re-executed the new block an asynchronous interrupt
came in?

Does changing the above to:

  cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | CF_NOIRQ | n;

make the problem go away? It should ensure the next 1/2 instruction
block execute without checking for async events. See gen_tb_start() for
the gory details.

> | Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
> | Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
> | Trap target PC mismatch CPU 0
> | Expected:    23fd77a80
> | Encountered: 23fd77a84
> | warning: 44	./nptl/pthread_kill.c: No such file or directory
> | Couldn't get registers: No such process.
>
> It does show up with both single-core and multi-core VMs, so that at
> least eliminates some possibilities. Maybe :/
>
> The issue is nasty to reproduce in a way that allows any meaningful
> investigation. It usually involves sifting through many GBs of Qemu logs
> for maybe one occurance. We could add another testing/dummy plugin that
> just prints the PC for _any_ instruction executed and have a skript
> check for non-alternating Trace-lines from Qemu and that Plugin. But
> then we're talking nearly double the amount of Lines to look through
> with probably little additional information.
>
> Regards,
> Julian

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

Hi Alex,

Sorry for tha late reply.

January 9, 2025 at 5:33 PM, "Alex Bennée" wrote:
> "Julian Ganz" <neither@nut.email> writes:
> 
> (Add Richard to CC)
> 
> > 
> > Hi Pierrick,
> > 
> >  December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
> > 
> > > 
> > > On 12/2/24 11:41, Julian Ganz wrote:
> > >  > +static void insn_exec(unsigned int vcpu_index, void *userdata)
> > >  > +{
> > >  > + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
> > >  > + uint64_t pc = (uint64_t) userdata;
> > >  > + GString* report;
> > >  > +
> > >  > + if (state->has_next) {
> > >  > + if (state->next_pc != pc) {
> > >  > + report = g_string_new("Trap target PC mismatch\n");
> > >  > + g_string_append_printf(report,
> > >  > + "Expected: %"PRIx64"\nEncountered: %"
> > >  > + PRIx64"\n",
> > >  > + state->next_pc, pc);
> > >  > + qemu_plugin_outs(report->str);
> > >  > + if (abort_on_mismatch) {
> > >  > + g_abort();
> > >  > + }
> > >  > + g_string_free(report, true);
> > >  > + }
> > >  > + state->has_next = false;
> > >  > + }
> > >  > +}
> > >  > 
> > >  When booting an arm64 vm, I get this message:
> > >  Trap target PC mismatch
> > >  Expected: 23faf3a80
> > >  Encountered: 23faf3a84
> > > 
> >  A colleague of mine went to great lengths trying to track and reliably
> >  reproduce this. We think that it's something amiss with the existing
> >  instruction exec callback infrastructure. So... it's not something I'll
> >  be addressing with the next iteration as it's out of scope. We'll
> >  probably continue looking into it, though.
> > 
> >  The mismatch is reported perfectly normal and boring exceptions and
> >  interrupts with no indication of any differences to other (not reported)
> >  events that fire on a regular basis. Apparently, once in a blue moon
> >  (relatively speaking), for the first instruction of a handler (even
> >  though it is definitely executed and qemu does print a trace-line for
> >  that instruction):
> > 
> >  | Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
> >  | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
> >  | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
> >  | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
> >  | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
> >  | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
> >  | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
> >  | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
> >  | cpu_io_recompile: rewound execution of TB to 000000023fde7b90
> > 
> So this happens when an instruction that is not the last instruction of
> the block does some IO. As IO accesses can potentially change system
> state we can't allow more instructions to run in the block that might
> not have that change of state captured
> 
> cpu_io_recompile exits the loop and forces the next TranslationBlock to
> be only one (or maybe two instructions). We have to play games with
> instrumentation to avoid double counting execution:
> 
>  /*
>  * Exit the loop and potentially generate a new TB executing the
>  * just the I/O insns. We also limit instrumentation to memory
>  * operations only (which execute after completion) so we don't
>  * double instrument the instruction.
>  */
>  cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | n;
> 
> The instruction is in a weird state having both executed (from the
> plugin point of view) but not changed any state (stopped from doing MMIO
> until the next instruction).
> 
> > 
> > | Taking exception 5 [IRQ] on CPU 0
> >  | ...from EL1 to EL1
> >  | ...with ESR 0x0/0x3800000
> >  | ...with SPSR 0x20000305
> >  | ...with ELR 0x23fde7b90
> >  | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
> > 
> I guess before we re-executed the new block an asynchronous interrupt
> came in?
> 
> Does changing the above to:
> 
>  cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | CF_NOIRQ | n;
> 
> make the problem go away? It should ensure the next 1/2 instruction
> block execute without checking for async events. See gen_tb_start() for
> the gory details.

So my collegue was tracing this issue himself over the last week(a) and
arrived more or less at the same conclusion. According to him we don't
observe the issue anymore, either.

Thanks for the fix!

Regards,
Julian

On 1/9/25 08:33, Alex Bennée wrote:
> "Julian Ganz" <neither@nut.email> writes:
> 
> (Add Richard to CC)
> 
>> Hi Pierrick,
>>
>> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>>> On 12/2/24 11:41, Julian Ganz wrote:
>>>>   +static void insn_exec(unsigned int vcpu_index, void *userdata)
>>>>   +{
>>>>   + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
>>>>   + uint64_t pc = (uint64_t) userdata;
>>>>   + GString* report;
>>>>   +
>>>>   + if (state->has_next) {
>>>>   + if (state->next_pc != pc) {
>>>>   + report = g_string_new("Trap target PC mismatch\n");
>>>>   + g_string_append_printf(report,
>>>>   + "Expected: %"PRIx64"\nEncountered: %"
>>>>   + PRIx64"\n",
>>>>   + state->next_pc, pc);
>>>>   + qemu_plugin_outs(report->str);
>>>>   + if (abort_on_mismatch) {
>>>>   + g_abort();
>>>>   + }
>>>>   + g_string_free(report, true);
>>>>   + }
>>>>   + state->has_next = false;
>>>>   + }
>>>>   +}
>>>>
>>> When booting an arm64 vm, I get this message:
>>> Trap target PC mismatch
>>> Expected: 23faf3a80
>>> Encountered: 23faf3a84
>>
>> A colleague of mine went to great lengths trying to track and reliably
>> reproduce this. We think that it's something amiss with the existing
>> instruction exec callback infrastructure. So... it's not something I'll
>> be addressing with the next iteration as it's out of scope. We'll
>> probably continue looking into it, though.
>>
>> The mismatch is reported perfectly normal and boring exceptions and
>> interrupts with no indication of any differences to other (not reported)
>> events that fire on a regular basis. Apparently, once in a blue moon
>> (relatively speaking), for the first instruction of a handler (even
>> though it is definitely executed and qemu does print a trace-line for
>> that instruction):
>>
>> | Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
>> | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
>> | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
>> | cpu_io_recompile: rewound execution of TB to 000000023fde7b90
> 
> So this happens when an instruction that is not the last instruction of
> the block does some IO. As IO accesses can potentially change system
> state we can't allow more instructions to run in the block that might
> not have that change of state captured
> 
> cpu_io_recompile exits the loop and forces the next TranslationBlock to
> be only one (or maybe two instructions). We have to play games with
> instrumentation to avoid double counting execution:
> 
>      /*
>       * Exit the loop and potentially generate a new TB executing the
>       * just the I/O insns. We also limit instrumentation to memory
>       * operations only (which execute after completion) so we don't
>       * double instrument the instruction.
>       */
>      cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | n;
> 
> The instruction is in a weird state having both executed (from the
> plugin point of view) but not changed any state (stopped from doing MMIO
> until the next instruction).
> 
>> | Taking exception 5 [IRQ] on CPU 0
>> | ...from EL1 to EL1
>> | ...with ESR 0x0/0x3800000
>> | ...with SPSR 0x20000305
>> | ...with ELR 0x23fde7b90
>> | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
> 
> I guess before we re-executed the new block an asynchronous interrupt
> came in?
> 
> Does changing the above to:
> 
>    cpu->cflags_next_tb = curr_cflags(cpu) | CF_MEMI_ONLY | CF_NOIRQ | n;
> 
> make the problem go away? It should ensure the next 1/2 instruction
> block execute without checking for async events. See gen_tb_start() for
> the gory details.
> 

Thanks, it solves the problem indeed.
I was not sure why this specific block was reexecuted in the case of an IRQ.

>> | Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
>> | Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
>> | Trap target PC mismatch CPU 0
>> | Expected:    23fd77a80
>> | Encountered: 23fd77a84
>> | warning: 44	./nptl/pthread_kill.c: No such file or directory
>> | Couldn't get registers: No such process.
>>
>> It does show up with both single-core and multi-core VMs, so that at
>> least eliminates some possibilities. Maybe :/
>>
>> The issue is nasty to reproduce in a way that allows any meaningful
>> investigation. It usually involves sifting through many GBs of Qemu logs
>> for maybe one occurance. We could add another testing/dummy plugin that
>> just prints the PC for _any_ instruction executed and have a skript
>> check for non-alternating Trace-lines from Qemu and that Plugin. But
>> then we're talking nearly double the amount of Lines to look through
>> with probably little additional information.
>>
>> Regards,
>> Julian
> 

Hi Julian,

On 12/20/24 03:47, Julian Ganz wrote:
> Hi Pierrick,
> 
> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>> On 12/2/24 11:41, Julian Ganz wrote:
>>>   +static void insn_exec(unsigned int vcpu_index, void *userdata)
>>>   +{
>>>   + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
>>>   + uint64_t pc = (uint64_t) userdata;
>>>   + GString* report;
>>>   +
>>>   + if (state->has_next) {
>>>   + if (state->next_pc != pc) {
>>>   + report = g_string_new("Trap target PC mismatch\n");
>>>   + g_string_append_printf(report,
>>>   + "Expected: %"PRIx64"\nEncountered: %"
>>>   + PRIx64"\n",
>>>   + state->next_pc, pc);
>>>   + qemu_plugin_outs(report->str);
>>>   + if (abort_on_mismatch) {
>>>   + g_abort();
>>>   + }
>>>   + g_string_free(report, true);
>>>   + }
>>>   + state->has_next = false;
>>>   + }
>>>   +}
>>>
>> When booting an arm64 vm, I get this message:
>> Trap target PC mismatch
>> Expected: 23faf3a80
>> Encountered: 23faf3a84
> 
> A colleague of mine went to great lengths trying to track and reliably
> reproduce this. We think that it's something amiss with the existing
> instruction exec callback infrastructure. So... it's not something I'll
> be addressing with the next iteration as it's out of scope. We'll
> probably continue looking into it, though.
> 
> The mismatch is reported perfectly normal and boring exceptions and
> interrupts with no indication of any differences to other (not reported)
> events that fire on a regular basis. Apparently, once in a blue moon
> (relatively speaking), for the first instruction of a handler (even
> though it is definitely executed and qemu does print a trace-line for
> that instruction):
> 
> | Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
> | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
> | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
> | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
> | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
> | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
> | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
> | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
> | cpu_io_recompile: rewound execution of TB to 000000023fde7b90
> | Taking exception 5 [IRQ] on CPU 0
> | ...from EL1 to EL1
> | ...with ESR 0x0/0x3800000
> | ...with SPSR 0x20000305
> | ...with ELR 0x23fde7b90
> | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
> | Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
> | Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
> | Trap target PC mismatch CPU 0
> | Expected:    23fd77a80
> | Encountered: 23fd77a84
> | warning: 44	./nptl/pthread_kill.c: No such file or directory
> | Couldn't get registers: No such process.
> 
> It does show up with both single-core and multi-core VMs, so that at
> least eliminates some possibilities. Maybe :/
> 
> The issue is nasty to reproduce in a way that allows any meaningful
> investigation. It usually involves sifting through many GBs of Qemu logs
> for maybe one occurance. We could add another testing/dummy plugin that
> just prints the PC for _any_ instruction executed and have a skript
> check for non-alternating Trace-lines from Qemu and that Plugin. But
> then we're talking nearly double the amount of Lines to look through
> with probably little additional information.
> 

Thanks for the investigation.
I could reproduce this with this command line:
./build/qemu-system-aarch64 -M virt -plugin 
./build/tests/tcg/plugins/libdiscons.so,abort=on -m 8G -device 
virtio-blk-pci,drive=root -drive 
if=none,id=root,file=/home/user/.work/images/debianaarch64.img -M virt 
-cpu max,pauth=off  -drive 
if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive 
if=pflash,file=/home/user/.work/images/AAVMF_VARS.fd -d plugin,in_asm,op 
-D crash.log

# -d plugin,in_asm,op allows to dump asm of every translated block, 
plugin output (for discon plugin), and tcg op generated.

It reliably crashes with a single address.
Looking at the debug output (crash.log):
----------------
IN:
0x23faf3a80:  d108c3ff  sub      sp, sp, #0x230
# => This bb has a single instruction as input

OP:
# this is the TB instrumentation
  ld_i32 loc0,env,$0xfffffffffffffff8
  brcond_i32 loc0,$0x0,lt,$L0
  st8_i32 $0x1,env,$0xfffffffffffffffc

  ---- 0000000000000a80 0000000000000000 0000000000000000
# => we can see that there is no call_plugin, looks like instrumentation 
# is not applied
  sub_i64 sp,sp,$0x230
  add_i64 pc,pc,$0x4
  goto_tb $0x1
  exit_tb $0x7f7eedd355c1
  set_label $L0
  exit_tb $0x7f7eedd355c3

----------------
IN:
0x23faf3a84:  a9b007e0  stp      x0, x1, [sp, #-0x100]!
0x23faf3a88:  a9010fe2  stp      x2, x3, [sp, #0x10]
...

OP:
  ld_i32 loc0,env,$0xfffffffffffffff8
  brcond_i32 loc0,$0x0,lt,$L0
  st8_i32 $0x0,env,$0xfffffffffffffffc

  ---- 0000000000000a84 0000000000000000 0000000000000000
# instruction is correctly applied
call plugin(0x7f7eec96d530),$0x1,$0,$0x0,$0x23faf3a84
  mov_i64 loc2,sp
  ...

Trap target PC mismatch
Expected:    23faf3a80
Encountered: 23faf3a84

The thing interesting here is that we can notice that 23faf3a80 is a 
translation block with a single instruction, and we can see that 
instrumentation is not applied for this instruction (call_plugin is not 
present).

Overall, it really looks like a bug on QEMU side, where we miss 
instrumenting something. I'll take a look. You can ignore this for now.

> Regards,
> Julian

Pierrick Bouvier <pierrick.bouvier@linaro.org> writes:

> Hi Julian,
>
> On 12/20/24 03:47, Julian Ganz wrote:
>> Hi Pierrick,
>> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>>> On 12/2/24 11:41, Julian Ganz wrote:
>>>>   +static void insn_exec(unsigned int vcpu_index, void *userdata)
>>>>   +{
>>>>   + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
>>>>   + uint64_t pc = (uint64_t) userdata;
>>>>   + GString* report;
>>>>   +
>>>>   + if (state->has_next) {
>>>>   + if (state->next_pc != pc) {
>>>>   + report = g_string_new("Trap target PC mismatch\n");
>>>>   + g_string_append_printf(report,
>>>>   + "Expected: %"PRIx64"\nEncountered: %"
>>>>   + PRIx64"\n",
>>>>   + state->next_pc, pc);
>>>>   + qemu_plugin_outs(report->str);
>>>>   + if (abort_on_mismatch) {
>>>>   + g_abort();
>>>>   + }
>>>>   + g_string_free(report, true);
>>>>   + }
>>>>   + state->has_next = false;
>>>>   + }
>>>>   +}
>>>>
>>> When booting an arm64 vm, I get this message:
>>> Trap target PC mismatch
>>> Expected: 23faf3a80
>>> Encountered: 23faf3a84
>> A colleague of mine went to great lengths trying to track and
>> reliably
>> reproduce this. We think that it's something amiss with the existing
>> instruction exec callback infrastructure. So... it's not something I'll
>> be addressing with the next iteration as it's out of scope. We'll
>> probably continue looking into it, though.
>> The mismatch is reported perfectly normal and boring exceptions and
>> interrupts with no indication of any differences to other (not reported)
>> events that fire on a regular basis. Apparently, once in a blue moon
>> (relatively speaking), for the first instruction of a handler (even
>> though it is definitely executed and qemu does print a trace-line for
>> that instruction):
>> | Trace 0: 0x7fffa0b03900
>> [00104004/000000023fde73b4/00000021/ff020200]
>> | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
>> | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
>> | cpu_io_recompile: rewound execution of TB to 000000023fde7b90
>> | Taking exception 5 [IRQ] on CPU 0
>> | ...from EL1 to EL1
>> | ...with ESR 0x0/0x3800000
>> | ...with SPSR 0x20000305
>> | ...with ELR 0x23fde7b90
>> | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
>> | Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
>> | Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
>> | Trap target PC mismatch CPU 0
>> | Expected:    23fd77a80
>> | Encountered: 23fd77a84
>> | warning: 44	./nptl/pthread_kill.c: No such file or directory
>> | Couldn't get registers: No such process.
>> It does show up with both single-core and multi-core VMs, so that at
>> least eliminates some possibilities. Maybe :/
>> The issue is nasty to reproduce in a way that allows any meaningful
>> investigation. It usually involves sifting through many GBs of Qemu logs
>> for maybe one occurance. We could add another testing/dummy plugin that
>> just prints the PC for _any_ instruction executed and have a skript
>> check for non-alternating Trace-lines from Qemu and that Plugin. But
>> then we're talking nearly double the amount of Lines to look through
>> with probably little additional information.
>> 
>
> Thanks for the investigation.
> I could reproduce this with this command line:
> ./build/qemu-system-aarch64 -M virt -plugin
> ./build/tests/tcg/plugins/libdiscons.so,abort=on -m 8G -device
> virtio-blk-pci,drive=root -drive
> if=none,id=root,file=/home/user/.work/images/debianaarch64.img -M virt
> -cpu max,pauth=off  -drive
> if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive
> if=pflash,file=/home/user/.work/images/AAVMF_VARS.fd -d
> plugin,in_asm,op -D crash.log
>
> # -d plugin,in_asm,op allows to dump asm of every translated block,
>    plugin output (for discon plugin), and tcg op generated.
>
> It reliably crashes with a single address.
> Looking at the debug output (crash.log):
> ----------------
> IN:
> 0x23faf3a80:  d108c3ff  sub      sp, sp, #0x230
> # => This bb has a single instruction as input
>
> OP:
> # this is the TB instrumentation
>  ld_i32 loc0,env,$0xfffffffffffffff8
>  brcond_i32 loc0,$0x0,lt,$L0
>  st8_i32 $0x1,env,$0xfffffffffffffffc
>
>  ---- 0000000000000a80 0000000000000000 0000000000000000
> # => we can see that there is no call_plugin, looks like
>   instrumentation # is not applied

That is expected. We have previously called the instrumentation for the
instruction in the block that triggered cpu_io_recompile() so we suppress
everything apart from memory instrumentation for the re-execution so we
don't double count.

>  sub_i64 sp,sp,$0x230
>  add_i64 pc,pc,$0x4
>  goto_tb $0x1
>  exit_tb $0x7f7eedd355c1
>  set_label $L0
>  exit_tb $0x7f7eedd355c3
>
> ----------------
> IN:
> 0x23faf3a84:  a9b007e0  stp      x0, x1, [sp, #-0x100]!
> 0x23faf3a88:  a9010fe2  stp      x2, x3, [sp, #0x10]
> ...
>
> OP:
>  ld_i32 loc0,env,$0xfffffffffffffff8
>  brcond_i32 loc0,$0x0,lt,$L0
>  st8_i32 $0x0,env,$0xfffffffffffffffc
>
>  ---- 0000000000000a84 0000000000000000 0000000000000000
> # instruction is correctly applied
> call plugin(0x7f7eec96d530),$0x1,$0,$0x0,$0x23faf3a84
>  mov_i64 loc2,sp
>  ...
>
> Trap target PC mismatch
> Expected:    23faf3a80
> Encountered: 23faf3a84
>
> The thing interesting here is that we can notice that 23faf3a80 is a
> translation block with a single instruction, and we can see that
> instrumentation is not applied for this instruction (call_plugin is
> not present).
>
> Overall, it really looks like a bug on QEMU side, where we miss
> instrumenting something. I'll take a look. You can ignore this for
> now.

See my other email. I think the bug was allowing an async IRQ to
interfere with our "special" single instruction block.

>
>> Regards,
>> Julian

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

On 12/20/24 13:17, Pierrick Bouvier wrote:
> Hi Julian,
> 
> On 12/20/24 03:47, Julian Ganz wrote:
>> Hi Pierrick,
>>
>> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>>> On 12/2/24 11:41, Julian Ganz wrote:
>>>>    +static void insn_exec(unsigned int vcpu_index, void *userdata)
>>>>    +{
>>>>    + struct cpu_state *state = qemu_plugin_scoreboard_find(states, vcpu_index);
>>>>    + uint64_t pc = (uint64_t) userdata;
>>>>    + GString* report;
>>>>    +
>>>>    + if (state->has_next) {
>>>>    + if (state->next_pc != pc) {
>>>>    + report = g_string_new("Trap target PC mismatch\n");
>>>>    + g_string_append_printf(report,
>>>>    + "Expected: %"PRIx64"\nEncountered: %"
>>>>    + PRIx64"\n",
>>>>    + state->next_pc, pc);
>>>>    + qemu_plugin_outs(report->str);
>>>>    + if (abort_on_mismatch) {
>>>>    + g_abort();
>>>>    + }
>>>>    + g_string_free(report, true);
>>>>    + }
>>>>    + state->has_next = false;
>>>>    + }
>>>>    +}
>>>>
>>> When booting an arm64 vm, I get this message:
>>> Trap target PC mismatch
>>> Expected: 23faf3a80
>>> Encountered: 23faf3a84
>>
>> A colleague of mine went to great lengths trying to track and reliably
>> reproduce this. We think that it's something amiss with the existing
>> instruction exec callback infrastructure. So... it's not something I'll
>> be addressing with the next iteration as it's out of scope. We'll
>> probably continue looking into it, though.
>>
>> The mismatch is reported perfectly normal and boring exceptions and
>> interrupts with no indication of any differences to other (not reported)
>> events that fire on a regular basis. Apparently, once in a blue moon
>> (relatively speaking), for the first instruction of a handler (even
>> though it is definitely executed and qemu does print a trace-line for
>> that instruction):
>>
>> | Trace 0: 0x7fffa0b03900 [00104004/000000023fde73b4/00000021/ff020200]
>> | Trace 0: 0x7fffa02d9580 [00104004/000000023fde72b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dfc40 [00104004/000000023fde7338/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03d00 [00104004/000000023fde73d4/00000021/ff020200]
>> | Trace 0: 0x7fffa0b03e80 [00104004/000000023fde73d8/00000021/ff020200]
>> | Trace 0: 0x7fffa0b04140 [00104004/000000023fde7408/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd6c0 [00104004/000000023fde70b8/00000021/ff020200]
>> | Trace 0: 0x7fffa02dd800 [00104004/000000023fde7b90/00000021/ff020200]
>> | cpu_io_recompile: rewound execution of TB to 000000023fde7b90
>> | Taking exception 5 [IRQ] on CPU 0
>> | ...from EL1 to EL1
>> | ...with ESR 0x0/0x3800000
>> | ...with SPSR 0x20000305
>> | ...with ELR 0x23fde7b90
>> | ...to EL1 PC 0x23fd77a80 PSTATE 0x23c5
>> | Trace 0: 0x7fffa13a8340 [00104004/000000023fd77a80/00000021/ff021201]
>> | Trace 0: 0x7fffa13a8480 [00104004/000000023fd77a84/00000021/ff020200]
>> | Trap target PC mismatch CPU 0
>> | Expected:    23fd77a80
>> | Encountered: 23fd77a84
>> | warning: 44	./nptl/pthread_kill.c: No such file or directory
>> | Couldn't get registers: No such process.
>>
>> It does show up with both single-core and multi-core VMs, so that at
>> least eliminates some possibilities. Maybe :/
>>
>> The issue is nasty to reproduce in a way that allows any meaningful
>> investigation. It usually involves sifting through many GBs of Qemu logs
>> for maybe one occurance. We could add another testing/dummy plugin that
>> just prints the PC for _any_ instruction executed and have a skript
>> check for non-alternating Trace-lines from Qemu and that Plugin. But
>> then we're talking nearly double the amount of Lines to look through
>> with probably little additional information.
>>
> 
> Thanks for the investigation.
> I could reproduce this with this command line:
> ./build/qemu-system-aarch64 -M virt -plugin
> ./build/tests/tcg/plugins/libdiscons.so,abort=on -m 8G -device
> virtio-blk-pci,drive=root -drive
> if=none,id=root,file=/home/user/.work/images/debianaarch64.img -M virt
> -cpu max,pauth=off  -drive
> if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive
> if=pflash,file=/home/user/.work/images/AAVMF_VARS.fd -d plugin,in_asm,op
> -D crash.log
> 
> # -d plugin,in_asm,op allows to dump asm of every translated block,
> plugin output (for discon plugin), and tcg op generated.
> 
> It reliably crashes with a single address.
> Looking at the debug output (crash.log):
> ----------------
> IN:
> 0x23faf3a80:  d108c3ff  sub      sp, sp, #0x230
> # => This bb has a single instruction as input
> 
> OP:
> # this is the TB instrumentation
>    ld_i32 loc0,env,$0xfffffffffffffff8
>    brcond_i32 loc0,$0x0,lt,$L0
>    st8_i32 $0x1,env,$0xfffffffffffffffc
> 
>    ---- 0000000000000a80 0000000000000000 0000000000000000
> # => we can see that there is no call_plugin, looks like instrumentation
> # is not applied
>    sub_i64 sp,sp,$0x230
>    add_i64 pc,pc,$0x4
>    goto_tb $0x1
>    exit_tb $0x7f7eedd355c1
>    set_label $L0
>    exit_tb $0x7f7eedd355c3
> 
> ----------------
> IN:
> 0x23faf3a84:  a9b007e0  stp      x0, x1, [sp, #-0x100]!
> 0x23faf3a88:  a9010fe2  stp      x2, x3, [sp, #0x10]
> ...
> 
> OP:
>    ld_i32 loc0,env,$0xfffffffffffffff8
>    brcond_i32 loc0,$0x0,lt,$L0
>    st8_i32 $0x0,env,$0xfffffffffffffffc
> 
>    ---- 0000000000000a84 0000000000000000 0000000000000000
> # instruction is correctly applied
> call plugin(0x7f7eec96d530),$0x1,$0,$0x0,$0x23faf3a84
>    mov_i64 loc2,sp
>    ...
> 
> Trap target PC mismatch
> Expected:    23faf3a80
> Encountered: 23faf3a84
> 
> The thing interesting here is that we can notice that 23faf3a80 is a
> translation block with a single instruction, and we can see that
> instrumentation is not applied for this instruction (call_plugin is not
> present).
> 
> Overall, it really looks like a bug on QEMU side, where we miss
> instrumenting something. I'll take a look. You can ignore this for now.
> 

It seems like we have a problem to identify tb as mem_only. This was 
introduced to prevent double instrumentation of some memory access 
(touching MMIO), but it seems that as a result, we skip some 
instructions sometimes.

I need to dig into this further, but for now, you should be able to 
workaround this on your side with this patch:

diff --git a/plugins/api.c b/plugins/api.c
index 24ea64e2de5..6cb9d81a0a2 100644
--- a/plugins/api.c
+++ b/plugins/api.c
@@ -92,6 +92,7 @@ void 
qemu_plugin_register_vcpu_exit_cb(qemu_plugin_id_t id,

  static bool tb_is_mem_only(void)
  {
+    return false;
      return tb_cflags(tcg_ctx->gen_tb) & CF_MEMI_ONLY;
  }

>> Regards,
>> Julian
> 

Regards,
Pierrick

Hi Pierrick,

December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
> On 12/2/24 11:41, Julian Ganz wrote:
> 
> >  +/*
> >  + * Copyright (C) 2024, Julian Ganz <neither@nut.email>
> >  + *
> >  + * License: GNU GPL, version 2 or later.
> >  + * See the COPYING file in the top-level directory.
> >  + */
> > 
> Would be nice to include a description of the plugin here.

Agreed. I'll include one next time.

> When booting an arm64 vm, I get this message:
> Trap target PC mismatch
> Expected: 23faf3a80
> Encountered: 23faf3a84
> 
>  From what I understand, it means that the next_pc we have is incorrect.

Yes, this is indeed incorrect, and also a perfect example why this test
plugin exists. There are likely other errors lurking in target specific
code. Did you happen to also log interrupts? Do you remember what image
you used?

Btw: this also illustrates another issue I have with from_pc: we can
test the behavior for to_pc, but doing this meaningfully for from_pc
via a plugin is next to impossible because the instruction it points to
is not observable via an exec callback. At least not in the general
case, even not if we only consider a single type of event.

Regards,
Julian Ganz

On 12/5/24 05:10, Julian Ganz wrote:
> Hi Pierrick,
> 
> December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>> On 12/2/24 11:41, Julian Ganz wrote:
>>
>>>   +/*
>>>   + * Copyright (C) 2024, Julian Ganz <neither@nut.email>
>>>   + *
>>>   + * License: GNU GPL, version 2 or later.
>>>   + * See the COPYING file in the top-level directory.
>>>   + */
>>>
>> Would be nice to include a description of the plugin here.
> 
> Agreed. I'll include one next time.
> 
>> When booting an arm64 vm, I get this message:
>> Trap target PC mismatch
>> Expected: 23faf3a80
>> Encountered: 23faf3a84
>>
>>   From what I understand, it means that the next_pc we have is incorrect.
> 
> Yes, this is indeed incorrect, and also a perfect example why this test
> plugin exists. There are likely other errors lurking in target specific
> code. Did you happen to also log interrupts? Do you remember what image
> you used?

I used exactly this:

./build/qemu-system-aarch64 -plugin 
./build/tests/tcg/plugins/libdiscons.so -smp 4 -M virt -d plugin -m 8G 
-device virtio-blk-pci,drive=root -drive 
if=none,id=root,file=./debianaarch64.img -M virt -cpu max,pauth=off 
-drive if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive 
if=pflash,file=./AAVMF_VARS.fd

The arm64 image is a vanilla debian stable I installed.
AAVMF* files come from qemu-efi-aarch64 debian package.

> 
> Btw: this also illustrates another issue I have with from_pc: we can
> test the behavior for to_pc, but doing this meaningfully for from_pc
> via a plugin is next to impossible because the instruction it points to
> is not observable via an exec callback. At least not in the general
> case, even not if we only consider a single type of event.
>

We can store the next_expected pc for each instruction (from 
current_instruction + insn_length), and we should be able to compare 
that with the expected from_pc.
This is mostly what contrib/plugins/cflow.c does.

With that, we can test from_pc.

> Regards,
> Julian Ganz

Hi Pierrick,

December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
> On 12/5/24 05:10, Julian Ganz wrote:
> >  December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
> > > Trap target PC mismatch
> > >  Expected: 23faf3a80
> > >  Encountered: 23faf3a84
> > > 
> > >  From what I understand, it means that the next_pc we have is incorrect.
> > > 
> >  Yes, this is indeed incorrect, and also a perfect example why this test
> >  plugin exists. There are likely other errors lurking in target specific
> >  code. Did you happen to also log interrupts? Do you remember what image
> >  you used?
> > 
> I used exactly this:
> 
> ./build/qemu-system-aarch64 -plugin ./build/tests/tcg/plugins/libdiscons.so -smp 4 -M virt -d plugin -m 8G -device virtio-blk-pci,drive=root -drive if=none,id=root,file=./debianaarch64.img -M virt -cpu max,pauth=off -drive if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive if=pflash,file=./AAVMF_VARS.fd
> 
> The arm64 image is a vanilla debian stable I installed.
> AAVMF* files come from qemu-efi-aarch64 debian package.

Thanks! I will have a closer look and include a fix in the next iteration.

> > Btw: this also illustrates another issue I have with from_pc: we can
> >  test the behavior for to_pc, but doing this meaningfully for from_pc
> >  via a plugin is next to impossible because the instruction it points to
> >  is not observable via an exec callback. At least not in the general
> >  case, even not if we only consider a single type of event.
> > 
> We can store the next_expected pc for each instruction (from current_instruction + insn_length), and we should be able to compare that with the expected from_pc.
> This is mostly what contrib/plugins/cflow.c does.
> 
> With that, we can test from_pc.

I'm not confident that this will work reliably for branch, jump and
other "interesting" instructions. But I can have a closer look at the
cflow plugin and try to figure out how that plugin handles those cases.

Regards,
Julian Ganz

On 12/5/24 13:22, Julian Ganz wrote:
> Hi Pierrick,
> 
> December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
>> On 12/5/24 05:10, Julian Ganz wrote:
>>>   December 5, 2024 at 12:33 AM, "Pierrick Bouvier" wrote:
>>>> Trap target PC mismatch
>>>>   Expected: 23faf3a80
>>>>   Encountered: 23faf3a84
>>>>
>>>>   From what I understand, it means that the next_pc we have is incorrect.
>>>>
>>>   Yes, this is indeed incorrect, and also a perfect example why this test
>>>   plugin exists. There are likely other errors lurking in target specific
>>>   code. Did you happen to also log interrupts? Do you remember what image
>>>   you used?
>>>
>> I used exactly this:
>>
>> ./build/qemu-system-aarch64 -plugin ./build/tests/tcg/plugins/libdiscons.so -smp 4 -M virt -d plugin -m 8G -device virtio-blk-pci,drive=root -drive if=none,id=root,file=./debianaarch64.img -M virt -cpu max,pauth=off -drive if=pflash,readonly=on,file=/usr/share/AAVMF/AAVMF_CODE.fd -drive if=pflash,file=./AAVMF_VARS.fd
>>
>> The arm64 image is a vanilla debian stable I installed.
>> AAVMF* files come from qemu-efi-aarch64 debian package.
> 
> Thanks! I will have a closer look and include a fix in the next iteration.
> 
>>> Btw: this also illustrates another issue I have with from_pc: we can
>>>   test the behavior for to_pc, but doing this meaningfully for from_pc
>>>   via a plugin is next to impossible because the instruction it points to
>>>   is not observable via an exec callback. At least not in the general
>>>   case, even not if we only consider a single type of event.
>>>
>> We can store the next_expected pc for each instruction (from current_instruction + insn_length), and we should be able to compare that with the expected from_pc.
>> This is mostly what contrib/plugins/cflow.c does.
>>
>> With that, we can test from_pc.
> 
> I'm not confident that this will work reliably for branch, jump and
> other "interesting" instructions. But I can have a closer look at the
> cflow plugin and try to figure out how that plugin handles those cases.
> 

It won't work for latest instructions in a tb (because we don't know 
what will be the next one), but should be good for all the others cases.

> Regards,
> Julian Ganz

Hi Pierrick,

December 5, 2024 at 11:28 PM, "Pierrick Bouvier" wrote:
> On 12/5/24 13:22, Julian Ganz wrote:
> >  December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
> > > We can store the next_expected pc for each instruction (from current_instruction + insn_length), and we should be able to compare that with the expected from_pc.
> > >  This is mostly what contrib/plugins/cflow.c does.
> > > 
> > >  With that, we can test from_pc.
> > > 
> >  I'm not confident that this will work reliably for branch, jump and
> >  other "interesting" instructions. But I can have a closer look at the
> >  cflow plugin and try to figure out how that plugin handles those cases.
> > 
> It won't work for latest instructions in a tb (because we don't know what will be the next one), but should be good for all the others cases.

IIUC qemu will schedule interrupts "opportunistically" between tb
executions. If that's the case we'll observe interrupts exclusively
after the last instruction in a tb. That strikes me as a serious
limitation.

Regards,
Julian Ganz

On 12/6/24 00:42, Julian Ganz wrote:
> Hi Pierrick,
> 
> December 5, 2024 at 11:28 PM, "Pierrick Bouvier" wrote:
>> On 12/5/24 13:22, Julian Ganz wrote:
>>>   December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
>>>> We can store the next_expected pc for each instruction (from current_instruction + insn_length), and we should be able to compare that with the expected from_pc.
>>>>   This is mostly what contrib/plugins/cflow.c does.
>>>>
>>>>   With that, we can test from_pc.
>>>>
>>>   I'm not confident that this will work reliably for branch, jump and
>>>   other "interesting" instructions. But I can have a closer look at the
>>>   cflow plugin and try to figure out how that plugin handles those cases.
>>>
>> It won't work for latest instructions in a tb (because we don't know what will be the next one), but should be good for all the others cases.
> 
> IIUC qemu will schedule interrupts "opportunistically" between tb
> executions. If that's the case we'll observe interrupts exclusively
> after the last instruction in a tb. That strikes me as a serious
> limitation.
>

To reuse fancy vocabulary, maybe we should have a distinction between 
inferable interruptions (interrupt instruction) and uninferable 
interrupts, triggered by an external event.

In the latter, it *might* be acceptable to not provide a from_pc (let's 
say a value 0), because there is no useful information in itself, except 
creating random edges in the control flow graph, which we don't want to do.

What do you think of it?

> Regards,
> Julian Ganz

On 12/6/24 13:02, Pierrick Bouvier wrote:
> On 12/6/24 00:42, Julian Ganz wrote:
>> Hi Pierrick,
>>
>> December 5, 2024 at 11:28 PM, "Pierrick Bouvier" wrote:
>>> On 12/5/24 13:22, Julian Ganz wrote:
>>>>   December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
>>>>> We can store the next_expected pc for each instruction (from current_instruction + 
>>>>> insn_length), and we should be able to compare that with the expected from_pc.
>>>>>   This is mostly what contrib/plugins/cflow.c does.
>>>>>
>>>>>   With that, we can test from_pc.
>>>>>
>>>>   I'm not confident that this will work reliably for branch, jump and
>>>>   other "interesting" instructions. But I can have a closer look at the
>>>>   cflow plugin and try to figure out how that plugin handles those cases.
>>>>
>>> It won't work for latest instructions in a tb (because we don't know what will be the 
>>> next one), but should be good for all the others cases.
>>
>> IIUC qemu will schedule interrupts "opportunistically" between tb
>> executions. If that's the case we'll observe interrupts exclusively
>> after the last instruction in a tb. That strikes me as a serious
>> limitation.
>>
> 
> To reuse fancy vocabulary, maybe we should have a distinction between inferable 
> interruptions (interrupt instruction) and uninferable interrupts, triggered by an external 
> event.
> 
> In the latter, it *might* be acceptable to not provide a from_pc (let's say a value 0), 
> because there is no useful information in itself, except creating random edges in the 
> control flow graph, which we don't want to do.
> 
> What do you think of it?

I think you both are over-complicating things.

Always, env->pc (or whatever) within cc->cpu_exec_interrupt *is* where the interrupt is 
recognized, and *is* where the discontinuity occurs.  Report that.

Just because some device interrupts are deferred to the end of the TB, that makes no 
difference.  There is no "right" answer for timing between execution and asynchronous 
interrupts.


r~

Hi Richard,

December 6, 2024 at 8:42 PM, "Richard Henderson" wrote:
> On 12/6/24 13:02, Pierrick Bouvier wrote:
> > On 12/6/24 00:42, Julian Ganz wrote:
> > > IIUC qemu will schedule interrupts "opportunistically" between tb
> > >  executions. If that's the case we'll observe interrupts exclusively
> > >  after the last instruction in a tb. That strikes me as a serious
> > >  limitation.
> > > 
> >  To reuse fancy vocabulary, maybe we should have a distinction between inferable > interruptions (interrupt instruction) and uninferable interrupts, triggered by an external > event.
> >  In the latter, it *might* be acceptable to not provide a from_pc (let's say a value 0), > because there is no useful information in itself, except creating random edges in the > control flow graph, which we don't want to do.
> >  What do you think of it?
> > 
> I think you both are over-complicating things.
> 
> Always, env->pc (or whatever) within cc->cpu_exec_interrupt *is* where the interrupt is recognized, and *is* where the discontinuity occurs. Report that.

Glad to hear. This means what I naïvely did for most targets should be
correct at least in this regard.

Regards,
Julian

On 12/6/24 11:42, Richard Henderson wrote:
> On 12/6/24 13:02, Pierrick Bouvier wrote:
>> On 12/6/24 00:42, Julian Ganz wrote:
>>> Hi Pierrick,
>>>
>>> December 5, 2024 at 11:28 PM, "Pierrick Bouvier" wrote:
>>>> On 12/5/24 13:22, Julian Ganz wrote:
>>>>>    December 5, 2024 at 6:30 PM, "Pierrick Bouvier" wrote:
>>>>>> We can store the next_expected pc for each instruction (from current_instruction +
>>>>>> insn_length), and we should be able to compare that with the expected from_pc.
>>>>>>    This is mostly what contrib/plugins/cflow.c does.
>>>>>>
>>>>>>    With that, we can test from_pc.
>>>>>>
>>>>>    I'm not confident that this will work reliably for branch, jump and
>>>>>    other "interesting" instructions. But I can have a closer look at the
>>>>>    cflow plugin and try to figure out how that plugin handles those cases.
>>>>>
>>>> It won't work for latest instructions in a tb (because we don't know what will be the
>>>> next one), but should be good for all the others cases.
>>>
>>> IIUC qemu will schedule interrupts "opportunistically" between tb
>>> executions. If that's the case we'll observe interrupts exclusively
>>> after the last instruction in a tb. That strikes me as a serious
>>> limitation.
>>>
>>
>> To reuse fancy vocabulary, maybe we should have a distinction between inferable
>> interruptions (interrupt instruction) and uninferable interrupts, triggered by an external
>> event.
>>
>> In the latter, it *might* be acceptable to not provide a from_pc (let's say a value 0),
>> because there is no useful information in itself, except creating random edges in the
>> control flow graph, which we don't want to do.
>>
>> What do you think of it?
> 
> I think you both are over-complicating things.
> 
> Always, env->pc (or whatever) within cc->cpu_exec_interrupt *is* where the interrupt is
> recognized, and *is* where the discontinuity occurs.  Report that.
> 

Do we have an architecture agnostic pc representation, or do we have to 
add this for every target in {arch}_cpu_exec_interrupt?

Beyond the scope of interruptions, are we guaranteed this instruction 
pointer (per arch) is always updated between instructions? Any corner cases?

> Just because some device interrupts are deferred to the end of the TB, that makes no
> difference.  There is no "right" answer for timing between execution and asynchronous
> interrupts.
> 
> 
> r~

On 12/6/24 14:40, Pierrick Bouvier wrote:
> Do we have an architecture agnostic pc representation, or do we have to add this for every 
> target in {arch}_cpu_exec_interrupt?

We have CPUClass.get_pc, which is almost certainly what you want.

The call to TCGCPUOps.cpu_exec_interrupt is only a hint that an interrupt might be ready: 
interrupts can still be masked, etc.

 From the current bool return value you can tell if a discontinuity actually occurred. 
But if you want to categorize that event in any way you need to update each architecture.

You could simplify such updates by changing the return type from bool to an enum.  While 
you would have to simultaneously update all targets for the change in function signature, 
if you select enumerators such that 0 -> no-op and 1 -> uncategorized, then you can also 
tell if a target has been updated.  Because this is still C, the current return true/false 
statements will Just Work.  :-)

On the other hand, the previous patches to add plugin calls to each cpu_exec_interrupt are 
in the end approximately the same level of difficulty, and is more straightforward, so YMMV.


> Beyond the scope of interruptions, are we guaranteed this instruction pointer (per arch) 
> is always updated between instructions? Any corner cases?

Not "between instructions" or even "between TB".  But you are guaranteed that pc is 
updated by the time we get to cpu_handle_interrupt, where cpu_exec_interrupt is called.


r~

Hi Richard,

December 6, 2024 at 11:56 PM, "Richard Henderson" wrote:
> On 12/6/24 14:40, Pierrick Bouvier wrote:
> 
> > 
> > Do we have an architecture agnostic pc representation, or do we have to add this for every > target in {arch}_cpu_exec_interrupt?
> > 
> We have CPUClass.get_pc, which is almost certainly what you want.

I was wondering about this but honestly failed to do so until the
current series was done. I'll definitely use this for to_pc in the next
iteration. I'll still need to gather from_pc "manually", but that's ok.

> The call to TCGCPUOps.cpu_exec_interrupt is only a hint that an interrupt might be ready: interrupts can still be masked, etc.
> 
>  From the current bool return value you can tell if a discontinuity actually occurred. But if you want to categorize that event in any way you need to update each architecture.
> 
> You could simplify such updates by changing the return type from bool to an enum. While you would have to simultaneously update all targets for the change in function signature, if you select enumerators such that 0 -> no-op and 1 -> uncategorized, then you can also tell if a target has been updated. Because this is still C, the current return true/false statements will Just Work. :-)
> 
> On the other hand, the previous patches to add plugin calls to each cpu_exec_interrupt are in the end approximately the same level of difficulty, and is more straightforward, so YMMV.

Good to hear. I think I'll stick to the current setup. It likely also
probably makes things easier or less awkward if the API is extended to
cover things like branches and jumps in the future.

Regards,
Julian