| Message ID | 4bd519d008cac6b319be7c5ce144e741f7210031.1636973694.git.quic_saipraka@quicinc.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | tracing/rwmmio/arm64: Add support to trace register reads/writes | expand |
On Mon, 15 Nov 2021 11:33:29 +0000, Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: > > From: Prasad Sodagudi <psodagud@codeaurora.org> > > 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 > cases, > > * If the access to the register space is unclocked, for example: if > there is an access to multimedia(MM) block registers without MM > clocks. > > * 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@codeaurora.org> > [saiprakash: Rewrote commit msg and trace event field edits] > Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com> > --- > > 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. Thanks, M.
On 11/19/2021 7:13 PM, Marc Zyngier wrote: > On Mon, 15 Nov 2021 11:33:29 +0000, > Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: >> From: Prasad Sodagudi <psodagud@codeaurora.org> >> >> 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 >> cases, >> >> * If the access to the register space is unclocked, for example: if >> there is an access to multimedia(MM) block registers without MM >> clocks. >> >> * 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@codeaurora.org> >> [saiprakash: Rewrote commit msg and trace event field edits] >> Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com> >> --- >> >> 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. > > Thanks, > > M. > 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. Thanks, Sai
On Fri, 19 Nov 2021 14:07:09 +0000, Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: > > On 11/19/2021 7:13 PM, Marc Zyngier wrote: > > On Mon, 15 Nov 2021 11:33:29 +0000, > > Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: > >> From: Prasad Sodagudi <psodagud@codeaurora.org> > >> [...] > >> 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. > > > > Thanks, > > > > M. > > > > 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. Yup. I wouldn't be surprised if MMIO accessors were getting directly inlined at the wrong location and creating havoc. For example: writel(readl(addr1) | 1, addr2); If you're not careful about capturing the result of the read rather than the read itself, you can end-up with something really funky. No idea if that's what is happening, but a disassembly of the generated code could tell you. M.
On 11/19/2021 7:47 PM, Marc Zyngier wrote: > On Fri, 19 Nov 2021 14:07:09 +0000, > Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: >> On 11/19/2021 7:13 PM, Marc Zyngier wrote: >>> On Mon, 15 Nov 2021 11:33:29 +0000, >>> Sai Prakash Ranjan <quic_saipraka@quicinc.com> wrote: >>>> From: Prasad Sodagudi <psodagud@codeaurora.org> >>>> > [...] > >>>> 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. >>> >>> Thanks, >>> >>> M. >>> >> 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. > Yup. I wouldn't be surprised if MMIO accessors were getting directly > inlined at the wrong location and creating havoc. For example: > > writel(readl(addr1) | 1, addr2); > > If you're not careful about capturing the result of the read rather > than the read itself, you can end-up with something really funky. No > idea if that's what is happening, but a disassembly of the generated > code could tell you. > > M. > I did that initially (compare the disassembly in working and non-working case) but didn't find anything noticeable, maybe I need to look some more. Thanks for the suggestion. Thanks, Sai
diff --git a/include/trace/events/rwmmio.h b/include/trace/events/rwmmio.h new file mode 100644 index 000000000000..1687abf8e7a3 --- /dev/null +++ b/include/trace/events/rwmmio.h @@ -0,0 +1,59 @@ +/* SPDX-License-Identifier: GPL-2.0-only */ +/* + * Copyright (c) 2021 Qualcomm Innovation Center, Inc. All rights reserved. + */ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM rwmmio + +#if !defined(_TRACE_RWMMIO_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_RWMMIO_H + +#include <linux/tracepoint.h> + +TRACE_EVENT(rwmmio_write, + + TP_PROTO(unsigned long fn, const char *width, volatile void __iomem *addr), + + TP_ARGS(fn, width, addr), + + TP_STRUCT__entry( + __field(u64, fn) + __field(u64, addr) + __string(width, width) + ), + + TP_fast_assign( + __entry->fn = fn; + __entry->addr = (u64)(void *)addr; + __assign_str(width, width); + ), + + TP_printk("%pS %s addr=%#llx", + (void *)(unsigned long)__entry->fn, __get_str(width), __entry->addr) +); + +TRACE_EVENT(rwmmio_read, + + TP_PROTO(unsigned long fn, const char *width, const volatile void __iomem *addr), + + TP_ARGS(fn, width, addr), + + TP_STRUCT__entry( + __field(u64, fn) + __field(u64, addr) + __string(width, width) + ), + + TP_fast_assign( + __entry->fn = fn; + __entry->addr = (u64)(void *)addr; + __assign_str(width, width); + ), + + TP_printk("%pS %s addr=%#llx", + (void *)(unsigned long)__entry->fn, __get_str(width), __entry->addr) +); + +#endif /* _TRACE_RWMMIO_H */ + +#include <trace/define_trace.h> diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig index 420ff4bc67fd..9f55bcc51de1 100644 --- a/kernel/trace/Kconfig +++ b/kernel/trace/Kconfig @@ -95,6 +95,13 @@ config RING_BUFFER_ALLOW_SWAP Allow the use of ring_buffer_swap_cpu. Adds a very slight overhead to tracing when enabled. +config TRACE_MMIO_ACCESS + bool "Register read/write tracing" + depends on TRACING + help + Create tracepoints for MMIO read/write operations. These trace events + can be used for logging all MMIO read/write operations. + config PREEMPTIRQ_TRACEPOINTS bool depends on TRACE_PREEMPT_TOGGLE || TRACE_IRQFLAGS diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile index bedc5caceec7..a3d16e1a5abd 100644 --- a/kernel/trace/Makefile +++ b/kernel/trace/Makefile @@ -99,5 +99,6 @@ obj-$(CONFIG_BOOTTIME_TRACING) += trace_boot.o obj-$(CONFIG_FTRACE_RECORD_RECURSION) += trace_recursion_record.o obj-$(CONFIG_TRACEPOINT_BENCHMARK) += trace_benchmark.o +obj-$(CONFIG_TRACE_MMIO_ACCESS) += trace_readwrite.o libftrace-y := ftrace.o diff --git a/kernel/trace/trace_readwrite.c b/kernel/trace/trace_readwrite.c new file mode 100644 index 000000000000..334e21f70c62 --- /dev/null +++ b/kernel/trace/trace_readwrite.c @@ -0,0 +1,29 @@ +// SPDX-License-Identifier: GPL-2.0-only +/* + * Register read and write tracepoints + * + * Copyright (c) 2021 Qualcomm Innovation Center, Inc. All rights reserved. + */ + +#include <linux/ftrace.h> +#include <linux/mmio-instrumented.h> +#include <linux/module.h> + +#define CREATE_TRACE_POINTS +#include <trace/events/rwmmio.h> + +#ifdef CONFIG_TRACE_MMIO_ACCESS +void log_write_mmio(const char *width, volatile void __iomem *addr) +{ + trace_rwmmio_write(CALLER_ADDR0, width, addr); +} +EXPORT_SYMBOL_GPL(log_write_mmio); +EXPORT_TRACEPOINT_SYMBOL_GPL(rwmmio_write); + +void log_read_mmio(const char *width, const volatile void __iomem *addr) +{ + trace_rwmmio_read(CALLER_ADDR0, width, addr); +} +EXPORT_SYMBOL_GPL(log_read_mmio); +EXPORT_TRACEPOINT_SYMBOL_GPL(rwmmio_read); +#endif /* CONFIG_TRACE_MMIO_ACCESS */