Re: [PATCH] contrib/plugins: add execlog to log instruction execution and memory access

["Alex Bennée" <alex.bennee@linaro.org>]

Alexandre IOOSS <erdnaxe@crans.org> writes:

> [[PGP Signed Part:Undecided]]
> On 6/15/21 6:47 PM, Alexandre IOOSS wrote:
>> On 6/15/21 10:22 AM, Alex Bennée wrote:
>>> Mahmoud Mandour <ma.mandourr@gmail.com> writes:
>>>> On 14/06/2021 11:01, Alexandre Iooss wrote:
>>>>> +}
>>>>> +
>>>>> +/**
>>>>> + * Log instruction execution
>>>>> + */
>>>>> +static void vcpu_insn_exec(unsigned int cpu_index, void *udata)
>>>>> +{
>>>>> +    char *insn_disas = (char *)udata;
>>>>> +
>>>>> +    /* Add data to execution log */
>>>>> +    fprintf(output, "insn: %s\n", insn_disas);
>>>
>>>    insn, 0x%08lx, disas
>>>
>>> Currently however on a multi-threaded execution you will potentially
>>> loose any synchronisation between the insn_exec and any memory operation
>>> associated with it. If you really just care about what's tickling
>>> hardware you could just drop the insn_exec callback and pass the
>>> instruction information via udata to the vcpu_mem callback. You could
>>> then dump everything in one line:
>>>
>>>    0xPC, ld [x1], x2, 0xADDR, load|store
>>>
>>> you wouldn't dump other instructions leading up to that though.
>> You are correct, this is indeed an issue and it's currently making
>> my life really hard when I try to apply a side-channel model on the
>> memory interactions.
>> I prefer to log all instructions, so I need to use vcpu_mem_cb when
>> it's a memory instruction, or vcpu_insn_exec_cb if it's not.
>
> If I always set vcpu_mem_cb and vcpu_insn_exec_cb, then an user can do
> a bit of postprocessing of the data to merge lines that correspond to
> memory interactions. Example of output (Cortex-M0 in Thumb mode):
>
> ```
> # vaddr, opcode, disassembly, [load/store, memory addr, device]
> 0xa14, 0xf87f42b4, "cmp r4, r6"
> 0xa16, 0xd206, "bhs #0xa26"
> 0xa18, 0xfff94803, "ldr r0, [pc, #0xc]"
> 0xa18, 0xfff94803, "ldr r0, [pc, #0xc]", load, 0x00010a28, RAM
> 0xa1a, 0xf989f000, "bl #0xd30"
> 0xd30, 0xfff9b510, "push {r4, lr}"
> 0xd30, 0xfff9b510, "push {r4, lr}", store, 0x20003ee0, RAM
> 0xd30, 0xfff9b510, "push {r4, lr}", store, 0x20003ee4, RAM
> 0xd32, 0xf9893014, "adds r0, #0x14"
> 0xd34, 0xf9c8f000, "bl #0x10c8"
> 0x10c8, 0xfff96c43, "ldr r3, [r0, #0x44]"
> 0x10c8, 0xfff96c43, "ldr r3, [r0, #0x44]", load, 0x200000e4, RAM
> ```

To be honest the post-processing is probably as workable solution as
anything else.

>
> If we don't want to call `vcpu_insn_exec_cb` when `vcpu_mem_cb` is
> triggered, then I would have either to:
>
> 1. Implement load/store instructions matchers, similar to what is done
> in `howvec.c` plugin.

This is probably fairly easy for most RISCs with sane encodings.

> 2. Implement instructions mnemonic matchers (using the output of
> qemu_plugin_insn_disas).

I wouldn't rely on textual formatting and reverse parsing the data.

> 3. Use Capstone and disassemble a second time each instructions.

The disassembly memory belongs to the plugin until it frees it so there
is no reason why you can't cache the data. If you share the same
callback data between the insn and mem callbacks you could just cache
the data in the insn callback and only print it out in the memory
callback. If you run another insn callback without having run a memory
callback then you know the last insn was a non-memory affecting one and
you print it out then before caching the current data. For a single
thread this would still look coherent and will be coherent per core if
you take care to cache in a per-cpu aware structure.

> What is your opinion on these solutions? Maybe for a first version we
> can keep it simple?

There is no problem with keeping it simple - and it certainly shouldn't
hold up merging. It can always be improved upon later ;-)

>
> Thanks,
> -- Alexandre
>
> [[End of PGP Signed Part]]


-- 
Alex Bennée