Re: [RFC PATCH 22/24] contrib/plugins: Allow to log registers

[Akihiko Odaki]

On 2023/08/15 0:21, Alex Bennée wrote:
> Akihiko Odaki <akihiko.odaki@daynix.com> writes:
>
> > This demonstrates how a register can be read from a plugin.
>
> I think it would be a little more useful as a demo if it tracked changes
> to the register state rather than dumping it for every line executed.
>
> > Signed-off-by: Akihiko Odaki <akihiko.odaki@daynix.com>
> > ---
> >   docs/devel/tcg-plugins.rst |  10 ++-
> >   contrib/plugins/execlog.c  | 130 ++++++++++++++++++++++++++++---------
> >   2 files changed, 108 insertions(+), 32 deletions(-)
> >
> > diff --git a/docs/devel/tcg-plugins.rst b/docs/devel/tcg-plugins.rst
> > index 81dcd43a61..c9f8b27590 100644
> > --- a/docs/devel/tcg-plugins.rst
> > +++ b/docs/devel/tcg-plugins.rst
> > @@ -497,6 +497,15 @@ arguments if required::
> >     $ qemu-system-arm $(QEMU_ARGS) \
> >       -plugin ./contrib/plugins/libexeclog.so,ifilter=st1w,afilter=0x40001808 
> > -d plugin
> >   
> > +This plugin can also dump a specified register. The specification of register
> > +follows `GDB standard target features 
> > <https://sourceware.org/gdb/onlinedocs/gdb/Standard-Target-Features.html>`__.
> > +
> > +Specify the name of the feature that contains the register and the name of the
> > +register with ``rfile`` and ``reg`` options, respectively::
> > +
> > +  $ qemu-system-arm $(QEMU_ARGS) \
> > +    -plugin ./contrib/plugins/libexeclog.so,rfile=org.gnu.gdb.arm.core,reg=sp 
> > -d plugin
> > +
> >   - contrib/plugins/cache.c
> >   
> >   Cache modelling plugin that measures the performance of a given L1 cache
> > @@ -583,4 +592,3 @@ The following API is generated from the inline 
> > documentation in
> >   include the full kernel-doc annotations.
> >   
> >   .. kernel-doc:: include/qemu/qemu-plugin.h
> > -
> > diff --git a/contrib/plugins/execlog.c b/contrib/plugins/execlog.c
> > index ce67acf145..031ad67fbb 100644
> > --- a/contrib/plugins/execlog.c
> > +++ b/contrib/plugins/execlog.c
> > @@ -15,27 +15,42 @@
> >   
> >   #include <qemu-plugin.h>
> >   
> > +typedef struct CPU {
> > +    /* Store last executed instruction on each vCPU as a GString */
> > +    GString *last_exec;
> > +    GByteArray *reg_buf;
> > +
> > +    int reg;
> > +} CPU;
> > +
> >   QEMU_PLUGIN_EXPORT int qemu_plugin_version = QEMU_PLUGIN_VERSION;
> >   
> > -/* Store last executed instruction on each vCPU as a GString */
> > -static GPtrArray *last_exec;
> > +static CPU *cpus;
> > +static int num_cpus;
> >   static GRWLock expand_array_lock;
> >   
> >   static GPtrArray *imatches;
> >   static GArray *amatches;
> >   
> > +static char *rfile_name;
> > +static char *reg_name;
> > +
> >   /*
> > - * Expand last_exec array.
> > + * Expand cpu array.
> >    *
> >    * As we could have multiple threads trying to do this we need to
> >    * serialise the expansion under a lock.
> >    */
> > -static void expand_last_exec(int cpu_index)
> > +static void expand_cpu(int cpu_index)
> >   {
> > -    g_rw_lock_writer_unlock(&expand_array_lock);
> > -    while (cpu_index >= last_exec->len) {
> > -        GString *s = g_string_new(NULL);
> > -        g_ptr_array_add(last_exec, s);
> > +    g_rw_lock_writer_lock(&expand_array_lock);
> > +    if (cpu_index >= num_cpus) {
> > +        cpus = g_realloc_n(cpus, cpu_index + 1, sizeof(*cpus));
> > +        while (cpu_index >= num_cpus) {
> > +            cpus[num_cpus].last_exec = g_string_new(NULL);
> > +            cpus[num_cpus].reg_buf = g_byte_array_new();
> > +            num_cpus++;
> > +        }
> >       }
> >       g_rw_lock_writer_unlock(&expand_array_lock);
> >   }
> > @@ -50,8 +65,8 @@ static void vcpu_mem(unsigned int cpu_index, 
> > qemu_plugin_meminfo_t info,
> >   
> >       /* Find vCPU in array */
> >       g_rw_lock_reader_lock(&expand_array_lock);
> > -    g_assert(cpu_index < last_exec->len);
> > -    s = g_ptr_array_index(last_exec, cpu_index);
> > +    g_assert(cpu_index < num_cpus);
> > +    s = cpus[cpu_index].last_exec;
> >       g_rw_lock_reader_unlock(&expand_array_lock);
> >   
> >       /* Indicate type of memory access */
> > @@ -77,28 +92,35 @@ static void vcpu_mem(unsigned int cpu_index, 
> > qemu_plugin_meminfo_t info,
> >    */
> >   static void vcpu_insn_exec(unsigned int cpu_index, void *udata)
> >   {
> > -    GString *s;
> > +    CPU cpu;
> > +    int n;
> > +    int i;
> >   
> >       /* Find or create vCPU in array */
> >       g_rw_lock_reader_lock(&expand_array_lock);
> > -    if (cpu_index >= last_exec->len) {
> > -        g_rw_lock_reader_unlock(&expand_array_lock);
> > -        expand_last_exec(cpu_index);
> > -        g_rw_lock_reader_lock(&expand_array_lock);
> > -    }
> > -    s = g_ptr_array_index(last_exec, cpu_index);
> > +    cpu = cpus[cpu_index];
> >       g_rw_lock_reader_unlock(&expand_array_lock);
> >   
> >       /* Print previous instruction in cache */
> > -    if (s->len) {
> > -        qemu_plugin_outs(s->str);
> > +    if (cpu.last_exec->len) {
> > +        qemu_plugin_outs(cpu.last_exec->str);
> >           qemu_plugin_outs("\n");
> >       }
> >   
> >       /* Store new instruction in cache */
> >       /* vcpu_mem will add memory access information to last_exec */
> > -    g_string_printf(s, "%u, ", cpu_index);
> > -    g_string_append(s, (char *)udata);
> > +    g_string_printf(cpu.last_exec, "%u, ", cpu_index);
> > +    g_string_append(cpu.last_exec, (char *)udata);
> > +
> > +    if (cpu.reg >= 0) {
> > +        g_string_append(cpu.last_exec, ", reg,");
> > +        n = qemu_plugin_read_register(cpu.reg_buf, cpu.reg);
> > +        for (i = 0; i < n; i++) {
> > +            g_string_append_printf(cpu.last_exec, " 0x%02X",
> > +                                   cpu.reg_buf->data[i]);
> > +        }
>
> so instead of:
>
>    0, 0x4001b4, 0xd10043ff, "sub sp, sp, #0x10", reg, 0x70 0xFF 0x7F 0x00 0x00 
> 0x40 0x00 0x00
>
> we could aim for something like:
>
>    0, 0x4001b4, 0xd10043ff, "sub sp, sp, #0x10", sp => 0x70ff7f0000400000

I changed this plugin so that it only emits register values when changed 
in v4 (I noticed I sent a wrong patch in v3), but it's not readable as 
much as your suggestion. It now emits like:

0, 0x4001b4, 0xd10043ff, "sub sp, sp, #0x10", reg, 70 ff 7f 00 00 40 00 00

This is because it's following the current CSV-like format of execlog 
output.

It will not also emit the value like 0x70ff7f0000400000 since the plugin 
does not know how the bytes should be interpreted. In fact, in this case 
I think it is in little endian and should be written as 0x4000007fff70. 
However the plugin does not have such knowledge.

> > +        g_byte_array_set_size(cpu.reg_buf, 0);
> > +    }
> >   }
> >   
> >   /**
> > @@ -167,8 +189,10 @@ static void vcpu_tb_trans(qemu_plugin_id_t id, struct 
> > qemu_plugin_tb *tb)
> >                                                QEMU_PLUGIN_MEM_RW, NULL);
> >   
> >               /* Register callback on instruction */
> > -            qemu_plugin_register_vcpu_insn_exec_cb(insn, vcpu_insn_exec,
> > -                                                   QEMU_PLUGIN_CB_NO_REGS, 
> > output);
> > +            qemu_plugin_register_vcpu_insn_exec_cb(
> > +                insn, vcpu_insn_exec,
> > +                rfile_name ? QEMU_PLUGIN_CB_R_REGS : QEMU_PLUGIN_CB_NO_REGS,
> > +                output);
> >   
> >               /* reset skip */
> >               skip = (imatches || amatches);
> > @@ -177,17 +201,53 @@ static void vcpu_tb_trans(qemu_plugin_id_t id, struct 
> > qemu_plugin_tb *tb)
> >       }
> >   }
> >   
> > +static void vcpu_init(qemu_plugin_id_t id, unsigned int vcpu_index)
> > +{
> > +    int reg = 0;
> > +    bool found = false;
> > +
> > +    expand_cpu(vcpu_index);
> > +
> > +    if (rfile_name) {
> > +        int i;
> > +        int j;
> > +        int n;
> > +
> > +        qemu_plugin_register_file_t *rfiles =
> > +            qemu_plugin_get_register_files(vcpu_index, &n);
> > +
> > +        for (i = 0; i < n; i++) {
> > +            if (g_strcmp0(rfiles[i].name, rfile_name) == 0) {
> > +                for (j = 0; j < rfiles[i].num_regs; j++) {
> > +                    if (g_strcmp0(rfiles[i].regs[j], reg_name) == 0) {
> > +                        reg += j;
> > +                        found = true;
> > +                        break;
> > +                    }
> > +                }
> > +                break;
> > +            }
> > +
> > +            reg += rfiles[i].num_regs;
> > +        }
> > +
> > +        g_free(rfiles);
> > +    }
> > +
> > +    g_rw_lock_writer_lock(&expand_array_lock);
> > +    cpus[vcpu_index].reg = found ? reg : -1;
> > +    g_rw_lock_writer_unlock(&expand_array_lock);
> > +}
> > +
> >   /**
> >    * On plugin exit, print last instruction in cache
> >    */
> >   static void plugin_exit(qemu_plugin_id_t id, void *p)
> >   {
> >       guint i;
> > -    GString *s;
> > -    for (i = 0; i < last_exec->len; i++) {
> > -        s = g_ptr_array_index(last_exec, i);
> > -        if (s->str) {
> > -            qemu_plugin_outs(s->str);
> > +    for (i = 0; i < num_cpus; i++) {
> > +        if (cpus[i].last_exec->str) {
> > +            qemu_plugin_outs(cpus[i].last_exec->str);
> >               qemu_plugin_outs("\n");
> >           }
> >       }
> > @@ -224,9 +284,7 @@ QEMU_PLUGIN_EXPORT int qemu_plugin_install(qemu_plugin_id_t 
> > id,
> >        * we don't know the size before emulation.
> >        */
> >       if (info->system_emulation) {
> > -        last_exec = g_ptr_array_sized_new(info->system.max_vcpus);
> > -    } else {
> > -        last_exec = g_ptr_array_new();
> > +        cpus = g_new(CPU, info->system.max_vcpus);
> >       }
> >   
> >       for (int i = 0; i < argc; i++) {
> > @@ -236,13 +294,23 @@ QEMU_PLUGIN_EXPORT int 
> > qemu_plugin_install(qemu_plugin_id_t id,
> >               parse_insn_match(tokens[1]);
> >           } else if (g_strcmp0(tokens[0], "afilter") == 0) {
> >               parse_vaddr_match(tokens[1]);
> > +        } else if (g_strcmp0(tokens[0], "rfile") == 0) {
> > +            rfile_name = g_strdup(tokens[1]);
> > +        } else if (g_strcmp0(tokens[0], "reg") == 0) {
> > +            reg_name = g_strdup(tokens[1]);
> >           } else {
> >               fprintf(stderr, "option parsing failed: %s\n", opt);
> >               return -1;
> >           }
> >       }
> >   
> > +    if ((!rfile_name) != (!reg_name)) {
> > +        fputs("file and reg need to be set at the same time\n", stderr);
> > +        return -1;
> > +    }
> > +
> >       /* Register translation block and exit callbacks */
> > +    qemu_plugin_register_vcpu_init_cb(id, vcpu_init);
> >       qemu_plugin_register_vcpu_tb_trans_cb(id, vcpu_tb_trans);
> >       qemu_plugin_register_atexit_cb(id, plugin_exit, NULL);