Re: [PATCHv4 1/2] tracing: Add register read/write tracing support

From: Sai Prakash Ranjan
Date: Fri Nov 19 2021 - 09:07:28 EST

On 11/19/2021 7:13 PM, Marc Zyngier wrote:
On Mon, 15 Nov 2021 11:33:29 +0000,
Sai Prakash Ranjan <quic_saipraka@xxxxxxxxxxx> wrote:
From: Prasad Sodagudi <psodagud@xxxxxxxxxxxxxx>

Generic MMIO read/write i.e., __raw_{read,write}{b,l,w,q} accessors
are typically used to read/write from/to memory mapped registers
and can cause hangs or some undefined behaviour in following few

* If the access to the register space is unclocked, for example: if
there is an access to multimedia(MM) block registers without MM

* If the register space is protected and not set to be accessible from
non-secure world, for example: only EL3 (EL: Exception level) access
is allowed and any EL2/EL1 access is forbidden.

* If xPU(memory/register protection units) is controlling access to
certain memory/register space for specific clients.

and more...

Such cases usually results in instant reboot/SErrors/NOC or interconnect
hangs and tracing these register accesses can be very helpful to debug
such issues during initial development stages and also in later stages.

So use ftrace trace events to log such MMIO register accesses which
provides rich feature set such as early enablement of trace events,
filtering capability, dumping ftrace logs on console and many more.

Sample output:

rwmmio_read: gic_peek_irq+0xd0/0xd8 readl addr=0xffff800010040104
rwmmio_write: gic_poke_irq+0xe4/0xf0 writel addr=0xffff800010040184
rwmmio_read: gic_do_wait_for_rwp+0x54/0x90 readl addr=0xffff800010040000
rwmmio_write: gic_set_affinity+0x1bc/0x1e8 writeq addr=0xffff800010046130

Signed-off-by: Prasad Sodagudi <psodagud@xxxxxxxxxxxxxx>
[saiprakash: Rewrote commit msg and trace event field edits]
Signed-off-by: Sai Prakash Ranjan <quic_saipraka@xxxxxxxxxxx>

Have dropped value parameter for mmio write trace event as that
was causing hangs in strange ways, i.e., if we pass any other
64bit value, it works fine but passing value would just hang.
Not just using the log apis, even simple trace_printk with value
printed would cause hang. It wasn't noticed in early version
because dyndbg would filter the logging in my system (I had
set it to trace only specific qcom directory) but once this
version starts recording all the reads/writes with value passed,
it just hangs system when rwmmio write event tracing is enabled.
Why is that so? Not being able to track the value written out makes
the feature pretty useless if you're not writing fixed values.

Reason why we wouldn't need value along with mmio write log is
that value can be easily deduced from the caller_name+offset which is
printed already by the rwmmio trace events which gives the exact
location of mmio writes and the value is easily known from the driver.
That's a very narrow view of what can be written in an MMIO
registers. We write dynamic values at all times, and if we are able to
trace MMIO writes, then the value written out must be part of the trace.

I'd rather you try and get to the bottom of this issue rather than
paper over it.



Sure, idea was to put it out in the open if anyone has any idea as to what might be happening
there since the version where directly instrumenting the raw read/write accessors in arm64/asm/io.h
was working fine casting doubts if this has to do something with inlining as Arnd mentioned before.