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 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 val=0x40
rwmmio_read: gic_do_wait_for_rwp+0x54/0x90 readl addr=0xffff800010040000
rwmmio_write: gic_set_affinity+0x1bc/0x1e8 writeq addr=0xffff800010046130 val=0x500
In addition to this, provide dynamic debug support to filter out unwanted
logs and limit trace to only specific files or directories since there can be
aweful lot of register trace events and we will be interested only in specific
drivers or subsystems which we will be working on. So introduce a new flag "e"
to filter these event tracing to specified input.
Example: Tracing register accesses for all drivers in drivers/soc/qcom/*
and the trace output is given below:
# dyndbg="file drivers/soc/qcom/* +e" trace_event=rwmmio
or
# echo "file drivers/soc/qcom/* +e" > /sys/kernel/debug/dynamic_debug/control
# cat /sys/kernel/debug/tracing/trace
rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
This series is a follow-up for the series [1] and a recent series [2] making use
of both.
[1] https://lore.kernel.org/lkml/[email protected]/
[2] https://lore.kernel.org/lkml/[email protected]/
Changes in v3:
* Create a generic mmio header for instrumented version (Earlier suggested in [1]
by Will Deacon and recently [2] by Greg to have a generic version first).
* Add dynamic debug support to filter out traces which can be very useful for targeted
debugging specific to subsystems or drivers.
* Few modifications to the rwmmio trace event fields to include the mmio width and print
addresses in hex.
* Rewrote commit msg to explain some more about usecases.
Prasad Sodagudi (1):
tracing: Add register read and write tracing support
Sai Prakash Ranjan (2):
arm64/io: Add a header for mmio access instrumentation
dynamic_debug: Add a flag for dynamic event tracing
arch/arm64/include/asm/io.h | 25 +++-----
arch/arm64/kvm/hyp/nvhe/Makefile | 2 +-
include/linux/dynamic_debug.h | 1 +
include/linux/mmio-instrumented.h | 95 +++++++++++++++++++++++++++++++
include/trace/events/rwmmio.h | 61 ++++++++++++++++++++
kernel/trace/Kconfig | 7 +++
kernel/trace/Makefile | 1 +
kernel/trace/trace_readwrite.c | 28 +++++++++
lib/dynamic_debug.c | 1 +
9 files changed, 204 insertions(+), 17 deletions(-)
create mode 100644 include/linux/mmio-instrumented.h
create mode 100644 include/trace/events/rwmmio.h
create mode 100644 kernel/trace/trace_readwrite.c
--
2.29.0
Debugging a specific driver or subsystem can be a lot easier if we can
trace events specific to that driver or subsystem. This type of
filtering can be achieved using existing dynamic debug library which
provides a way to filter based on files, functions and modules.
Using this, provide an additional flag 'e' to filter event tracing to
specified input.
For example, tracing all MMIO read/write can be overwhelming and of no
use when debugging a specific driver or a subsystem. So switch to
dynamic event tracing for register accesses.
Example: Tracing register accesses for all drivers in drivers/soc/qcom/*
and the trace output is given below:
# dyndbg="file drivers/soc/qcom/* +e" trace_event=rwmmio
or
# echo "file drivers/soc/qcom/* +e" > /sys/kernel/debug/dynamic_debug/control
# cat /sys/kernel/debug/tracing/trace
rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
Cc: Jason Baron <[email protected]>
Signed-off-by: Sai Prakash Ranjan <[email protected]>
---
include/linux/dynamic_debug.h | 1 +
include/linux/mmio-instrumented.h | 29 +++++++++++++++++++++++++++--
lib/dynamic_debug.c | 1 +
3 files changed, 29 insertions(+), 2 deletions(-)
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index dce631e678dd..80a1ae234a3b 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -32,6 +32,7 @@ struct _ddebug {
#define _DPRINTK_FLAGS_INCL_FUNCNAME (1<<2)
#define _DPRINTK_FLAGS_INCL_LINENO (1<<3)
#define _DPRINTK_FLAGS_INCL_TID (1<<4)
+#define _DPRINTK_FLAGS_EVENT (1<<5)
#define _DPRINTK_FLAGS_INCL_ANY \
(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
diff --git a/include/linux/mmio-instrumented.h b/include/linux/mmio-instrumented.h
index 4304224f3be4..4ff5af4bbee8 100644
--- a/include/linux/mmio-instrumented.h
+++ b/include/linux/mmio-instrumented.h
@@ -6,6 +6,7 @@
#ifndef _LINUX_MMIO_INSTRUMENTED_H
#define _LINUX_MMIO_INSTRUMENTED_H
+#include <linux/dynamic_debug.h>
#include <linux/tracepoint-defs.h>
/*
@@ -25,7 +26,7 @@ void log_read_mmio(const char *width, const volatile void __iomem *addr);
#define __raw_write(v, a, _l) ({ \
volatile void __iomem *_a = (a); \
if (tracepoint_enabled(rwmmio_write)) \
- log_write_mmio(__stringify(write##_l), v, _a); \
+ dynamic_log_write_mmio(__stringify(write##_l), v, _a);\
arch_raw_write##_l((v), _a); \
})
@@ -38,7 +39,7 @@ void log_read_mmio(const char *width, const volatile void __iomem *addr);
_t __a; \
const volatile void __iomem *_a = (a); \
if (tracepoint_enabled(rwmmio_read)) \
- log_read_mmio(__stringify(read##_l), _a); \
+ dynamic_log_read_mmio(__stringify(read##_l), _a);\
__a = arch_raw_read##_l(_a); \
__a; \
})
@@ -48,6 +49,26 @@ void log_read_mmio(const char *width, const volatile void __iomem *addr);
#define __raw_readl(a) __raw_read((a), l, u32)
#define __raw_readq(a) __raw_read((a), q, u64)
+#if defined(CONFIG_DYNAMIC_DEBUG)
+#define dynamic_log_write_mmio(width, value, addr) \
+do { \
+ DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, width); \
+ if (unlikely(descriptor.flags & _DPRINTK_FLAGS_EVENT)) \
+ log_write_mmio(width, value, addr); \
+} while (0)
+
+#define dynamic_log_read_mmio(width, addr) \
+do { \
+ DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, width); \
+ if (unlikely(descriptor.flags & _DPRINTK_FLAGS_EVENT)) \
+ log_read_mmio(width, addr); \
+} while (0)
+
+#else
+#define dynamic_log_write_mmio(width, val, addr) log_write_mmio(width, val, addr)
+#define dynamic_log_read_mmio(width, addr) log_read_mmio(width, addr)
+#endif /* CONFIG_DYNAMIC_DEBUG */
+
#else
#define __raw_writeb(v, a) arch_raw_writeb(v, a)
@@ -64,6 +85,10 @@ static inline void log_write_mmio(const char *width, u64 val,
volatile void __iomem *addr) {}
static inline void log_read_mmio(const char *width,
const volatile void __iomem *addr) {}
+static inline void dynamic_log_write_mmio(const char *width, u64 val,
+ volatile void __iomem *addr) {}
+static inline void dynamic_log_read_mmio(const char *width,
+ const volatile void __iomem *addr) {}
#endif /* CONFIG_TRACE_MMIO_ACCESS */
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index dd7f56af9aed..a852073089d9 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -87,6 +87,7 @@ static inline const char *trim_prefix(const char *path)
static struct { unsigned flag:8; char opt_char; } opt_array[] = {
{ _DPRINTK_FLAGS_PRINT, 'p' },
+ { _DPRINTK_FLAGS_EVENT, 'e' },
{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
--
2.29.0
From: Prasad Sodagudi <[email protected]>
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 val=0x40
rwmmio_read: gic_do_wait_for_rwp+0x54/0x90 readl addr=0xffff800010040000
rwmmio_write: gic_set_affinity+0x1bc/0x1e8 writeq addr=0xffff800010046130 val=0x500
Signed-off-by: Prasad Sodagudi <[email protected]>
[saiprakash: Rewrote commit msg and trace event field edits]
Signed-off-by: Sai Prakash Ranjan <[email protected]>
---
include/trace/events/rwmmio.h | 61 ++++++++++++++++++++++++++++++++++
kernel/trace/Kconfig | 7 ++++
kernel/trace/Makefile | 1 +
kernel/trace/trace_readwrite.c | 28 ++++++++++++++++
4 files changed, 97 insertions(+)
create mode 100644 include/trace/events/rwmmio.h
create mode 100644 kernel/trace/trace_readwrite.c
diff --git a/include/trace/events/rwmmio.h b/include/trace/events/rwmmio.h
new file mode 100644
index 000000000000..cb5261a559f8
--- /dev/null
+++ b/include/trace/events/rwmmio.h
@@ -0,0 +1,61 @@
+/* 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_MMIO_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_MMIO_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(rwmmio_write,
+
+ TP_PROTO(unsigned long fn, const char *width, u64 val, volatile void __iomem *addr),
+
+ TP_ARGS(fn, width, val, addr),
+
+ TP_STRUCT__entry(
+ __field(u64, fn)
+ __string(width, width)
+ __field(u64, val)
+ __field(u64, addr)
+ ),
+
+ TP_fast_assign(
+ __entry->fn = fn;
+ __assign_str(width, width);
+ __entry->val = val;
+ __entry->addr = (u64)addr;
+ ),
+
+ TP_printk("%pS %s addr=%#llx val=%#llx",
+ (void *)__entry->fn, __get_str(width), __entry->addr, __entry->val)
+);
+
+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)
+ __string(width, width)
+ __field(u64, addr)
+ ),
+
+ TP_fast_assign(
+ __entry->fn = fn;
+ __assign_str(width, width);
+ __entry->addr = (u64)addr;
+ ),
+
+ TP_printk("%pS %s addr=%#llx",
+ (void *)__entry->fn, __get_str(width), __entry->addr)
+);
+
+#endif /* _TRACE_MMIO_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..8fccb64a8c32
--- /dev/null
+++ b/kernel/trace/trace_readwrite.c
@@ -0,0 +1,28 @@
+// 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/module.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/rwmmio.h>
+
+#ifdef CONFIG_TRACE_MMIO_ACCESS
+void log_write_mmio(const char *width, u64 val, volatile void __iomem *addr)
+{
+ trace_rwmmio_write(CALLER_ADDR0, width, val, 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 */
--
2.29.0
On Tue, 9 Nov 2021 17:38:19 +0530
Sai Prakash Ranjan <[email protected]> wrote:
> From: Prasad Sodagudi <[email protected]>
>
> 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 val=0x40
> rwmmio_read: gic_do_wait_for_rwp+0x54/0x90 readl addr=0xffff800010040000
> rwmmio_write: gic_set_affinity+0x1bc/0x1e8 writeq addr=0xffff800010046130 val=0x500
>
> Signed-off-by: Prasad Sodagudi <[email protected]>
> [saiprakash: Rewrote commit msg and trace event field edits]
> Signed-off-by: Sai Prakash Ranjan <[email protected]>
> ---
> include/trace/events/rwmmio.h | 61 ++++++++++++++++++++++++++++++++++
> kernel/trace/Kconfig | 7 ++++
> kernel/trace/Makefile | 1 +
> kernel/trace/trace_readwrite.c | 28 ++++++++++++++++
> 4 files changed, 97 insertions(+)
> create mode 100644 include/trace/events/rwmmio.h
> create mode 100644 kernel/trace/trace_readwrite.c
>
> diff --git a/include/trace/events/rwmmio.h b/include/trace/events/rwmmio.h
> new file mode 100644
> index 000000000000..cb5261a559f8
> --- /dev/null
> +++ b/include/trace/events/rwmmio.h
> @@ -0,0 +1,61 @@
> +/* 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_MMIO_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_MMIO_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(rwmmio_write,
> +
> + TP_PROTO(unsigned long fn, const char *width, u64 val, volatile void __iomem *addr),
> +
> + TP_ARGS(fn, width, val, addr),
> +
> + TP_STRUCT__entry(
> + __field(u64, fn)
> + __string(width, width)
> + __field(u64, val)
> + __field(u64, addr)
For better space usage, move the __string to the end. Each of the u64
fields will take up 8 bytes, and the __string only takes up 4 (it's a 2
byte offset and 2 byte length, where the actual string lies at the end of
the event). Many archs will leave a 4 byte "hole" between the __string()
field and the u64 val field. If __string is at the end, it will go nicely
with the actual string that will be appended behind it.
> + ),
> +
> + TP_fast_assign(
> + __entry->fn = fn;
> + __assign_str(width, width);
> + __entry->val = val;
> + __entry->addr = (u64)addr;
> + ),
> +
> + TP_printk("%pS %s addr=%#llx val=%#llx",
> + (void *)__entry->fn, __get_str(width), __entry->addr, __entry->val)
> +);
> +
> +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)
> + __string(width, width)
> + __field(u64, addr)
Same here.
> + ),
> +
> + TP_fast_assign(
> + __entry->fn = fn;
> + __assign_str(width, width);
> + __entry->addr = (u64)addr;
> + ),
> +
> + TP_printk("%pS %s addr=%#llx",
> + (void *)__entry->fn, __get_str(width), __entry->addr)
> +);
> +
-- Steve
Hi Steve,
On 11/9/2021 7:24 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 17:38:19 +0530
> Sai Prakash Ranjan <[email protected]> wrote:
>
>> From: Prasad Sodagudi <[email protected]>
>>
>> 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 val=0x40
>> rwmmio_read: gic_do_wait_for_rwp+0x54/0x90 readl addr=0xffff800010040000
>> rwmmio_write: gic_set_affinity+0x1bc/0x1e8 writeq addr=0xffff800010046130 val=0x500
>>
>> Signed-off-by: Prasad Sodagudi <[email protected]>
>> [saiprakash: Rewrote commit msg and trace event field edits]
>> Signed-off-by: Sai Prakash Ranjan <[email protected]>
>> ---
>> include/trace/events/rwmmio.h | 61 ++++++++++++++++++++++++++++++++++
>> kernel/trace/Kconfig | 7 ++++
>> kernel/trace/Makefile | 1 +
>> kernel/trace/trace_readwrite.c | 28 ++++++++++++++++
>> 4 files changed, 97 insertions(+)
>> create mode 100644 include/trace/events/rwmmio.h
>> create mode 100644 kernel/trace/trace_readwrite.c
>>
>> diff --git a/include/trace/events/rwmmio.h b/include/trace/events/rwmmio.h
>> new file mode 100644
>> index 000000000000..cb5261a559f8
>> --- /dev/null
>> +++ b/include/trace/events/rwmmio.h
>> @@ -0,0 +1,61 @@
>> +/* 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_MMIO_H) || defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_MMIO_H
>> +
>> +#include <linux/tracepoint.h>
>> +
>> +TRACE_EVENT(rwmmio_write,
>> +
>> + TP_PROTO(unsigned long fn, const char *width, u64 val, volatile void __iomem *addr),
>> +
>> + TP_ARGS(fn, width, val, addr),
>> +
>> + TP_STRUCT__entry(
>> + __field(u64, fn)
>> + __string(width, width)
>> + __field(u64, val)
>> + __field(u64, addr)
> For better space usage, move the __string to the end. Each of the u64
> fields will take up 8 bytes, and the __string only takes up 4 (it's a 2
> byte offset and 2 byte length, where the actual string lies at the end of
> the event). Many archs will leave a 4 byte "hole" between the __string()
> field and the u64 val field. If __string is at the end, it will go nicely
> with the actual string that will be appended behind it.
Thanks for the informative suggestion, will make the change for the next
version.
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->fn = fn;
>> + __assign_str(width, width);
>> + __entry->val = val;
>> + __entry->addr = (u64)addr;
>> + ),
>> +
>> + TP_printk("%pS %s addr=%#llx val=%#llx",
>> + (void *)__entry->fn, __get_str(width), __entry->addr, __entry->val)
>> +);
>> +
>> +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)
>> + __string(width, width)
>> + __field(u64, addr)
> Same here.
Sure, will make the change.
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->fn = fn;
>> + __assign_str(width, width);
>> + __entry->addr = (u64)addr;
>> + ),
>> +
>> + TP_printk("%pS %s addr=%#llx",
>> + (void *)__entry->fn, __get_str(width), __entry->addr)
>> +);
>> +
> -- Steve
Thanks,
Sai
On Tue, 9 Nov 2021 17:38:21 +0530
Sai Prakash Ranjan <[email protected]> wrote:
> Debugging a specific driver or subsystem can be a lot easier if we can
> trace events specific to that driver or subsystem. This type of
> filtering can be achieved using existing dynamic debug library which
> provides a way to filter based on files, functions and modules.
>
> Using this, provide an additional flag 'e' to filter event tracing to
> specified input.
>
> For example, tracing all MMIO read/write can be overwhelming and of no
> use when debugging a specific driver or a subsystem. So switch to
> dynamic event tracing for register accesses.
>
> Example: Tracing register accesses for all drivers in drivers/soc/qcom/*
> and the trace output is given below:
>
> # dyndbg="file drivers/soc/qcom/* +e" trace_event=rwmmio
> or
> # echo "file drivers/soc/qcom/* +e" > /sys/kernel/debug/dynamic_debug/control
> # cat /sys/kernel/debug/tracing/trace
FYI, it's best to use /sys/kernel/tracing, as the debug/tracing is only
there for backward compatibility.
> rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
> rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
> rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
> rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
I'd much rather have a module name or something attached to the event that
ca be filtered on via the trace event filters, than having it determined by
some side effect done in another directory.
-- Steve
Hi Steve,
On 11/9/2021 9:19 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 17:38:21 +0530
> Sai Prakash Ranjan <[email protected]> wrote:
>
>> Debugging a specific driver or subsystem can be a lot easier if we can
>> trace events specific to that driver or subsystem. This type of
>> filtering can be achieved using existing dynamic debug library which
>> provides a way to filter based on files, functions and modules.
>>
>> Using this, provide an additional flag 'e' to filter event tracing to
>> specified input.
>>
>> For example, tracing all MMIO read/write can be overwhelming and of no
>> use when debugging a specific driver or a subsystem. So switch to
>> dynamic event tracing for register accesses.
>>
>> Example: Tracing register accesses for all drivers in drivers/soc/qcom/*
>> and the trace output is given below:
>>
>> # dyndbg="file drivers/soc/qcom/* +e" trace_event=rwmmio
>> or
>> # echo "file drivers/soc/qcom/* +e" > /sys/kernel/debug/dynamic_debug/control
>> # cat /sys/kernel/debug/tracing/trace
> FYI, it's best to use /sys/kernel/tracing, as the debug/tracing is only
> there for backward compatibility.
Ah I see, will correct it.
>> rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
>> rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
>> rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
>> rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
> I'd much rather have a module name or something attached to the event that
> ca be filtered on via the trace event filters, than having it determined by
> some side effect done in another directory.
I presume we don't have CALLER_MODULENAME0,1,2.. like CALLER_ADDR0,1,2
without which we
cannot insert the module name to this trace event since MMIO accessors
are defined in low level
arch headers and we won't get any useful module information from where
these accessors are
called. The function name and the offset is good enough to identify the
exact line and module after
post-processing with tools like GDB, objdump, so I feel we can keep the
trace event fields limited?
Thanks,
Sai
>
> -- Steve
On Tue, 9 Nov 2021 21:52:26 +0530
Sai Prakash Ranjan <[email protected]> wrote:
> >> rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
> >> rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
> >> rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
> >> rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
> > I'd much rather have a module name or something attached to the event that
> > ca be filtered on via the trace event filters, than having it determined by
> > some side effect done in another directory.
>
> I presume we don't have CALLER_MODULENAME0,1,2.. like CALLER_ADDR0,1,2
> without which we
> cannot insert the module name to this trace event since MMIO accessors
> are defined in low level
> arch headers and we won't get any useful module information from where
> these accessors are
> called. The function name and the offset is good enough to identify the
> exact line and module after
> post-processing with tools like GDB, objdump, so I feel we can keep the
> trace event fields limited?
I'm thinking we can pass the descriptor to the event and not have it record
it. We could add a new field type for defining the event. Something like:
__filter_field()
that has size zero in the event itself, but is available to the filtering
logic. Than perhaps we could pass that descriptor to the filter that has
all the information needed.
DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, width);
log_read_mmio(width, addr, descriptor);
Where descriptor is NULL when dynamic debug in disabled.
Have a way to pass that descriptor to the filtering logic (I'll have to
take a look into it) and then be able to use the normal filtering.
This way you could also create multiple instances, where one instance
records the events coming from one file, and the other records events from
another file, and not have just one big switch that disables all calls to
log_read_mmio().
-- Steve
On Tue, 9 Nov 2021 23:00:11 +0530
Sai Prakash Ranjan <[email protected]> wrote:
> Ah that's a very good idea, descriptor does contain the module, file name.
> We can probably even pass the module name,file name as string from the
> descriptor itself to event?
> Perhaps we can do that for all trace events and not just this trace
> event? Just like the trace event name displayed
> with trace events, perhaps have file name,module name displayed when
> dynamic debug is enabled? Filtering by
> filename is pretty useful since most of these usecases in debugging will
> be with respect to some driver or subsystems.
If we add this for all events, it would require a lot of changes to all
users of tracepoints, as it would require adding a new parameter to the
callbacks.
We could add a flag in the registering that states that the callback is OK
for it, and it passes that data as well.
Let me look into this for a bit. I may not have something this week, but
we should look into this more before adding little hacks that do this one
at a time like this patch.
-- Steve
Hi Steve,
On 11/9/2021 10:29 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 21:52:26 +0530
> Sai Prakash Ranjan <[email protected]> wrote:
>
>>>> rwmmio_read: rpmh_rsc_probe+0x35c/0x410 readl addr=0xffff80001071000c
>>>> rwmmio_read: rpmh_rsc_probe+0x3d0/0x410 readl addr=0xffff800010710004
>>>> rwmmio_write: rpmh_rsc_probe+0x3b0/0x410 writel addr=0xffff800010710d00 val=0x3
>>>> rwmmio_write: write_tcs_cmd+0x6c/0x78 writel addr=0xffff800010710d30 val=0x10108
>>> I'd much rather have a module name or something attached to the event that
>>> ca be filtered on via the trace event filters, than having it determined by
>>> some side effect done in another directory.
>> I presume we don't have CALLER_MODULENAME0,1,2.. like CALLER_ADDR0,1,2
>> without which we
>> cannot insert the module name to this trace event since MMIO accessors
>> are defined in low level
>> arch headers and we won't get any useful module information from where
>> these accessors are
>> called. The function name and the offset is good enough to identify the
>> exact line and module after
>> post-processing with tools like GDB, objdump, so I feel we can keep the
>> trace event fields limited?
> I'm thinking we can pass the descriptor to the event and not have it record
> it. We could add a new field type for defining the event. Something like:
>
> __filter_field()
>
> that has size zero in the event itself, but is available to the filtering
> logic. Than perhaps we could pass that descriptor to the filter that has
> all the information needed.
>
> DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, width);
> log_read_mmio(width, addr, descriptor);
>
> Where descriptor is NULL when dynamic debug in disabled.
>
> Have a way to pass that descriptor to the filtering logic (I'll have to
> take a look into it) and then be able to use the normal filtering.
>
> This way you could also create multiple instances, where one instance
> records the events coming from one file, and the other records events from
> another file, and not have just one big switch that disables all calls to
> log_read_mmio().
>
> -- Steve
Ah that's a very good idea, descriptor does contain the module, file name.
We can probably even pass the module name,file name as string from the
descriptor itself to event?
Perhaps we can do that for all trace events and not just this trace
event? Just like the trace event name displayed
with trace events, perhaps have file name,module name displayed when
dynamic debug is enabled? Filtering by
filename is pretty useful since most of these usecases in debugging will
be with respect to some driver or subsystems.
Thanks,
Sai
On 11/9/2021 11:10 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 23:00:11 +0530
> Sai Prakash Ranjan <[email protected]> wrote:
>
>> Ah that's a very good idea, descriptor does contain the module, file name.
>> We can probably even pass the module name,file name as string from the
>> descriptor itself to event?
>> Perhaps we can do that for all trace events and not just this trace
>> event? Just like the trace event name displayed
>> with trace events, perhaps have file name,module name displayed when
>> dynamic debug is enabled? Filtering by
>> filename is pretty useful since most of these usecases in debugging will
>> be with respect to some driver or subsystems.
> If we add this for all events, it would require a lot of changes to all
> users of tracepoints, as it would require adding a new parameter to the
> callbacks.
>
> We could add a flag in the registering that states that the callback is OK
> for it, and it passes that data as well.
>
> Let me look into this for a bit. I may not have something this week, but
> we should look into this more before adding little hacks that do this one
> at a time like this patch.
>
> -- Steve
Sure, thanks for the help and review. I can skip this patch adding
support for dynamic event tracing
till we have something concrete as the previous patches doesn't depend
on this.
Thanks,
Sai
On Tue, 9 Nov 2021 16:42:48 -0500
Jason Baron <[email protected]> wrote:
> Yeah there is a 'parallel' thread about adding the tracing ring buffer as
> a 'back end' to the dynamic debug stuff over here:
> https://lore.kernel.org/lkml/[email protected]/
As the maintainer of tracefs, why am I not Cc'd on that thread :-(
I'll have to look at that thread later (no time now).
>
> The attempt there is more generic but I realize now that it is adding the
> tracing to an 'instance' which is specific to dynamic debug which is
> being created via: trace_array_get_by_name(). I would prefer to just have
> it print to the 'main' trace buffer such that it's easier to read,
> although I guess they could still be consolidated via timestamps.
> Hmmm...I think there was a previous proposal to just add a single
> tracepoint (that takes a string) to the dynamic debug layer that could be
> called if a dynamic debug site is enabled for trace buffer output. Would
> that satisfy the ftrace level filtering requirements that you are looking
> for?
What we are looking at there is to pass the dynamic debug descriptor to the
trace event filtering logic, where you could filter on information passed
to it. For example, on a specific file if a trace event is called by
several different files or modules.
-- Steve
On 11/9/21 12:49 PM, Sai Prakash Ranjan wrote:
> On 11/9/2021 11:10 PM, Steven Rostedt wrote:
>> On Tue, 9 Nov 2021 23:00:11 +0530
>> Sai Prakash Ranjan <[email protected]> wrote:
>>
>>> Ah that's a very good idea, descriptor does contain the module, file name.
>>> We can probably even pass the module name,file name as string from the
>>> descriptor itself to event?
>>> Perhaps we can do that for all trace events and not just this trace
>>> event? Just like the trace event name displayed
>>> with trace events, perhaps have file name,module name displayed when
>>> dynamic debug is enabled? Filtering by
>>> filename is pretty useful since most of these usecases in debugging will
>>> be with respect to some driver or subsystems.
>> If we add this for all events, it would require a lot of changes to all
>> users of tracepoints, as it would require adding a new parameter to the
>> callbacks.
>>
>> We could add a flag in the registering that states that the callback is OK
>> for it, and it passes that data as well.
>>
>> Let me look into this for a bit. I may not have something this week, but
>> we should look into this more before adding little hacks that do this one
>> at a time like this patch.
>>
>> -- Steve
>
> Sure, thanks for the help and review. I can skip this patch adding support for dynamic event tracing
> till we have something concrete as the previous patches doesn't depend on this.
>
> Thanks,
> Sai
Hi,
Yeah there is a 'parallel' thread about adding the tracing ring buffer as a 'back end' to the dynamic debug stuff over here:
https://lore.kernel.org/lkml/[email protected]/
The attempt there is more generic but I realize now that it is adding the tracing to an 'instance' which is specific to dynamic debug which is being
created via: trace_array_get_by_name(). I would prefer to just have it print to the 'main' trace buffer such that it's easier to read, although I
guess they could still be consolidated via timestamps. Hmmm...I think there was a previous proposal to just add a single tracepoint (that takes a
string) to the dynamic debug layer that could be called if a dynamic debug site is enabled for trace buffer output. Would that satisfy the ftrace
level filtering requirements that you are looking for?
Thanks,
-Jason
On 11/9/21 4:51 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 16:42:48 -0500
> Jason Baron <[email protected]> wrote:
>
>> Yeah there is a 'parallel' thread about adding the tracing ring buffer as
>> a 'back end' to the dynamic debug stuff over here:
>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/[email protected]/__;!!GjvTz_vk!GdVm3olk4hfEx6PjfDDPg4cIbtY60aeqP0IOwu1-S0qJRBZ-OuvC5I_stkqniA$
>
> As the maintainer of tracefs, why am I not Cc'd on that thread :-(
>
> I'll have to look at that thread later (no time now).
Agreed - that's my bad. I meant to add you earlier in the discussion...
>
>>
>> The attempt there is more generic but I realize now that it is adding the
>> tracing to an 'instance' which is specific to dynamic debug which is
>> being created via: trace_array_get_by_name(). I would prefer to just have
>> it print to the 'main' trace buffer such that it's easier to read,
>> although I guess they could still be consolidated via timestamps.
>> Hmmm...I think there was a previous proposal to just add a single
>> tracepoint (that takes a string) to the dynamic debug layer that could be
>> called if a dynamic debug site is enabled for trace buffer output. Would
>> that satisfy the ftrace level filtering requirements that you are looking
>> for?
>
> What we are looking at there is to pass the dynamic debug descriptor to the
> trace event filtering logic, where you could filter on information passed
> to it. For example, on a specific file if a trace event is called by
> several different files or modules.
>
> -- Steve
Ok, Could this be done at the dynamic debug level as it can already match on specific files and line numbers currently?
Thanks,
-Jason
[ Hmm, should add Mathieu in on this discussion ]
On Tue, 9 Nov 2021 17:13:13 -0500
Jason Baron <[email protected]> wrote:
> > What we are looking at there is to pass the dynamic debug descriptor to the
> > trace event filtering logic, where you could filter on information passed
> > to it. For example, on a specific file if a trace event is called by
> > several different files or modules.
> >
> > -- Steve
>
> Ok, Could this be done at the dynamic debug level as it can already match
> on specific files and line numbers currently?
Not sure what you mean by that.
The idea was that this would only be enabled if dynamic debug is enabled
and that the DEFINE_DYNAMIC_DEBUG_METADATA() could be used at the
tracepoint function location (trace_foo()) by the tracepoint macros. And
then if one of the callbacks registered for the tracepoint had a
"dynamic_debug" flag set, it would be passed the descriptor in as a pointer.
And then, for example, the filtering logic of ftrace could then reference
the information of the event, if the user passed in something special.
# echo 'DEBUG_FILE ~ "drivers/soc/qcom/*"' > events/rwmmio/rwmmio_write/filter
# echo 1 > events/rwmmio/rwmmio_write/enable
And then only the rwmmio_write events that came from the qcom directory
would be printed.
We would create special event fields like "DEBUG_FILE", "DEBUG_FUNC",
"DEBUG_MOD", "DEBUG_LINE", etc, that could be used if dyndebug is enabled
in the kernel.
Of course this is going to bloat the kernel as it will create a dynamic
debug descriptor at every tracepoint location.
-- Steve
On 11/9/21 5:28 PM, Steven Rostedt wrote:
> [ Hmm, should add Mathieu in on this discussion ]
>
> On Tue, 9 Nov 2021 17:13:13 -0500
> Jason Baron <[email protected]> wrote:
>
>>> What we are looking at there is to pass the dynamic debug descriptor to the
>>> trace event filtering logic, where you could filter on information passed
>>> to it. For example, on a specific file if a trace event is called by
>>> several different files or modules.
>>>
>>> -- Steve
>>
>> Ok, Could this be done at the dynamic debug level as it can already match
>> on specific files and line numbers currently?
>
> Not sure what you mean by that.
I was just trying to say that via dynamic debug one could enable all debugs in a kernel source directory as in your example below via:
# echo "file drivers/soc/qcom/* +p" > /sys/kernel/debug/dynamic_debug/control
So if we are just looking for a printk here, one could just use pr_debug(). Or if we want that print to go the tracing ring buffer we have been
discussing how to add that as a 'backend' for dynamic debug as well.
If we want to use tracepionts, then yeah I think it's going to require adding the file, line, module data to each tracepoint site. I think this is
probably done via the tracing macros and then that could be filtered on, but yes that's going to add bloat.
The proposal here seems to be a mix of things - use the file control that dynamic debug already has to match on file name and then enable a tracepoint
that is behind it. That seems overly complex?
Thanks,
-Jason
>
> The idea was that this would only be enabled if dynamic debug is enabled
> and that the DEFINE_DYNAMIC_DEBUG_METADATA() could be used at the
> tracepoint function location (trace_foo()) by the tracepoint macros. And
> then if one of the callbacks registered for the tracepoint had a
> "dynamic_debug" flag set, it would be passed the descriptor in as a pointer.
>
> And then, for example, the filtering logic of ftrace could then reference
> the information of the event, if the user passed in something special.
>
> # echo 'DEBUG_FILE ~ "drivers/soc/qcom/*"' > events/rwmmio/rwmmio_write/filter
> # echo 1 > events/rwmmio/rwmmio_write/enable
>
> And then only the rwmmio_write events that came from the qcom directory
> would be printed.
>
> We would create special event fields like "DEBUG_FILE", "DEBUG_FUNC",
> "DEBUG_MOD", "DEBUG_LINE", etc, that could be used if dyndebug is enabled
> in the kernel.
>
> Of course this is going to bloat the kernel as it will create a dynamic
> debug descriptor at every tracepoint location.
>
> -- Steve
>
Hi Sai,
Thank you for the patch! Yet something to improve:
[auto build test ERROR on rostedt-trace/for-next]
[also build test ERROR on arm64/for-next/core linus/master v5.15 next-20211110]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Sai-Prakash-Ranjan/tracing-rwmmio-arm64-Add-support-to-trace-register-reads-writes/20211109-201049
base: https://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git for-next
config: arc-allyesconfig (attached as .config)
compiler: arceb-elf-gcc (GCC) 11.2.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
chmod +x ~/bin/make.cross
# https://github.com/0day-ci/linux/commit/d030401ce80c246ff0575c11e156122d869d10c2
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Sai-Prakash-Ranjan/tracing-rwmmio-arm64-Add-support-to-trace-register-reads-writes/20211109-201049
git checkout d030401ce80c246ff0575c11e156122d869d10c2
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-11.2.0 make.cross ARCH=arc
If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <[email protected]>
All errors (new ones prefixed by >>):
In file included from include/trace/define_trace.h:102,
from include/trace/events/rwmmio.h:61,
from kernel/trace/trace_readwrite.c:12:
include/trace/events/rwmmio.h: In function 'trace_raw_output_rwmmio_write':
>> include/trace/events/rwmmio.h:34:17: error: cast to pointer from integer of different size [-Werror=int-to-pointer-cast]
34 | (void *)__entry->fn, __get_str(width), __entry->addr, __entry->val)
| ^
include/trace/trace_events.h:399:34: note: in definition of macro 'DECLARE_EVENT_CLASS'
399 | trace_event_printf(iter, print); \
| ^~~~~
include/trace/trace_events.h:80:30: note: in expansion of macro 'PARAMS'
80 | PARAMS(print)); \
| ^~~~~~
include/trace/events/rwmmio.h:13:1: note: in expansion of macro 'TRACE_EVENT'
13 | TRACE_EVENT(rwmmio_write,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:33:9: note: in expansion of macro 'TP_printk'
33 | TP_printk("%pS %s addr=%#llx val=%#llx",
| ^~~~~~~~~
include/trace/events/rwmmio.h: In function 'trace_raw_output_rwmmio_read':
include/trace/events/rwmmio.h:56:18: error: cast to pointer from integer of different size [-Werror=int-to-pointer-cast]
56 | (void *)__entry->fn, __get_str(width), __entry->addr)
| ^
include/trace/trace_events.h:399:34: note: in definition of macro 'DECLARE_EVENT_CLASS'
399 | trace_event_printf(iter, print); \
| ^~~~~
include/trace/trace_events.h:80:30: note: in expansion of macro 'PARAMS'
80 | PARAMS(print)); \
| ^~~~~~
include/trace/events/rwmmio.h:37:1: note: in expansion of macro 'TRACE_EVENT'
37 | TRACE_EVENT(rwmmio_read,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:55:9: note: in expansion of macro 'TP_printk'
55 | TP_printk("%pS %s addr=%#llx",
| ^~~~~~~~~
In file included from include/trace/define_trace.h:102,
from include/trace/events/rwmmio.h:61,
from kernel/trace/trace_readwrite.c:12:
include/trace/events/rwmmio.h: In function 'trace_event_raw_event_rwmmio_write':
>> include/trace/events/rwmmio.h:30:33: error: cast from pointer to integer of different size [-Werror=pointer-to-int-cast]
30 | __entry->addr = (u64)addr;
| ^
include/trace/trace_events.h:743:11: note: in definition of macro 'DECLARE_EVENT_CLASS'
743 | { assign; } \
| ^~~~~~
include/trace/trace_events.h:79:30: note: in expansion of macro 'PARAMS'
79 | PARAMS(assign), \
| ^~~~~~
include/trace/events/rwmmio.h:13:1: note: in expansion of macro 'TRACE_EVENT'
13 | TRACE_EVENT(rwmmio_write,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:26:9: note: in expansion of macro 'TP_fast_assign'
26 | TP_fast_assign(
| ^~~~~~~~~~~~~~
include/trace/events/rwmmio.h: In function 'trace_event_raw_event_rwmmio_read':
include/trace/events/rwmmio.h:52:33: error: cast from pointer to integer of different size [-Werror=pointer-to-int-cast]
52 | __entry->addr = (u64)addr;
| ^
include/trace/trace_events.h:743:11: note: in definition of macro 'DECLARE_EVENT_CLASS'
743 | { assign; } \
| ^~~~~~
include/trace/trace_events.h:79:30: note: in expansion of macro 'PARAMS'
79 | PARAMS(assign), \
| ^~~~~~
include/trace/events/rwmmio.h:37:1: note: in expansion of macro 'TRACE_EVENT'
37 | TRACE_EVENT(rwmmio_read,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:49:9: note: in expansion of macro 'TP_fast_assign'
49 | TP_fast_assign(
| ^~~~~~~~~~~~~~
In file included from include/trace/define_trace.h:103,
from include/trace/events/rwmmio.h:61,
from kernel/trace/trace_readwrite.c:12:
include/trace/events/rwmmio.h: In function 'perf_trace_rwmmio_write':
>> include/trace/events/rwmmio.h:30:33: error: cast from pointer to integer of different size [-Werror=pointer-to-int-cast]
30 | __entry->addr = (u64)addr;
| ^
include/trace/perf.h:66:11: note: in definition of macro 'DECLARE_EVENT_CLASS'
66 | { assign; } \
| ^~~~~~
include/trace/trace_events.h:79:30: note: in expansion of macro 'PARAMS'
79 | PARAMS(assign), \
| ^~~~~~
include/trace/events/rwmmio.h:13:1: note: in expansion of macro 'TRACE_EVENT'
13 | TRACE_EVENT(rwmmio_write,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:26:9: note: in expansion of macro 'TP_fast_assign'
26 | TP_fast_assign(
| ^~~~~~~~~~~~~~
include/trace/events/rwmmio.h: In function 'perf_trace_rwmmio_read':
include/trace/events/rwmmio.h:52:33: error: cast from pointer to integer of different size [-Werror=pointer-to-int-cast]
52 | __entry->addr = (u64)addr;
| ^
include/trace/perf.h:66:11: note: in definition of macro 'DECLARE_EVENT_CLASS'
66 | { assign; } \
| ^~~~~~
include/trace/trace_events.h:79:30: note: in expansion of macro 'PARAMS'
79 | PARAMS(assign), \
| ^~~~~~
include/trace/events/rwmmio.h:37:1: note: in expansion of macro 'TRACE_EVENT'
37 | TRACE_EVENT(rwmmio_read,
| ^~~~~~~~~~~
include/trace/events/rwmmio.h:49:9: note: in expansion of macro 'TP_fast_assign'
49 | TP_fast_assign(
| ^~~~~~~~~~~~~~
kernel/trace/trace_readwrite.c: At top level:
>> kernel/trace/trace_readwrite.c:15:6: error: no previous prototype for 'log_write_mmio' [-Werror=missing-prototypes]
15 | void log_write_mmio(const char *width, u64 val, volatile void __iomem *addr)
| ^~~~~~~~~~~~~~
>> kernel/trace/trace_readwrite.c:22:6: error: no previous prototype for 'log_read_mmio' [-Werror=missing-prototypes]
22 | void log_read_mmio(const char *width, const volatile void __iomem *addr)
| ^~~~~~~~~~~~~
In file included from include/linux/perf_event.h:25,
from include/linux/trace_events.h:10,
from include/trace/trace_events.h:21,
from include/trace/define_trace.h:102,
from include/trace/events/rwmmio.h:61,
from kernel/trace/trace_readwrite.c:12:
arch/arc/include/asm/perf_event.h:126:27: error: 'arc_pmu_cache_map' defined but not used [-Werror=unused-const-variable=]
126 | static const unsigned int arc_pmu_cache_map[C(MAX)][C(OP_MAX)][C(RESULT_MAX)] = {
| ^~~~~~~~~~~~~~~~~
arch/arc/include/asm/perf_event.h:91:27: error: 'arc_pmu_ev_hw_map' defined but not used [-Werror=unused-const-variable=]
91 | static const char * const arc_pmu_ev_hw_map[] = {
| ^~~~~~~~~~~~~~~~~
cc1: all warnings being treated as errors
vim +34 include/trace/events/rwmmio.h
14
15 TP_PROTO(unsigned long fn, const char *width, u64 val, volatile void __iomem *addr),
16
17 TP_ARGS(fn, width, val, addr),
18
19 TP_STRUCT__entry(
20 __field(u64, fn)
21 __string(width, width)
22 __field(u64, val)
23 __field(u64, addr)
24 ),
25
26 TP_fast_assign(
27 __entry->fn = fn;
28 __assign_str(width, width);
29 __entry->val = val;
> 30 __entry->addr = (u64)addr;
31 ),
32
33 TP_printk("%pS %s addr=%#llx val=%#llx",
> 34 (void *)__entry->fn, __get_str(width), __entry->addr, __entry->val)
35 );
36
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/[email protected]
----- On Nov 9, 2021, at 5:28 PM, rostedt [email protected] wrote:
> [ Hmm, should add Mathieu in on this discussion ]
>
> On Tue, 9 Nov 2021 17:13:13 -0500
> Jason Baron <[email protected]> wrote:
>
>> > What we are looking at there is to pass the dynamic debug descriptor to the
>> > trace event filtering logic, where you could filter on information passed
>> > to it. For example, on a specific file if a trace event is called by
>> > several different files or modules.
>> >
>> > -- Steve
>>
>> Ok, Could this be done at the dynamic debug level as it can already match
>> on specific files and line numbers currently?
>
> Not sure what you mean by that.
>
> The idea was that this would only be enabled if dynamic debug is enabled
> and that the DEFINE_DYNAMIC_DEBUG_METADATA() could be used at the
> tracepoint function location (trace_foo()) by the tracepoint macros. And
> then if one of the callbacks registered for the tracepoint had a
> "dynamic_debug" flag set, it would be passed the descriptor in as a pointer.
>
> And then, for example, the filtering logic of ftrace could then reference
> the information of the event, if the user passed in something special.
>
> # echo 'DEBUG_FILE ~ "drivers/soc/qcom/*"' > events/rwmmio/rwmmio_write/filter
> # echo 1 > events/rwmmio/rwmmio_write/enable
>
> And then only the rwmmio_write events that came from the qcom directory
> would be printed.
>
> We would create special event fields like "DEBUG_FILE", "DEBUG_FUNC",
> "DEBUG_MOD", "DEBUG_LINE", etc, that could be used if dyndebug is enabled
> in the kernel.
>
> Of course this is going to bloat the kernel as it will create a dynamic
> debug descriptor at every tracepoint location.
I think there is indeed value in doing this. Where I'm not sure is regarding
how we allow this to be enabled/configured.
The way I see it, it might be sufficient and simpler to do just something along
those lines:
- Introduce a new struct tracepoint_caller_info, which would contain information
about file, line number and module name where each trace_*() statement is located.
- Add a new CONFIG_TRACEPOINT_CALLER_INFO which generates this new structure at
build time for kernel and modules. This would indeed bloat the kernel, but it's
a build-time configurable trade-off.
- Change the prototype for the tracepoint callbacks to add an additional argument
"struct tracepoint_caller_info *caller_info". When CONFIG_TRACEPOINT_CALLER_INFO
is disabled, simply have this pointer be NULL. When CONFIG_TRACEPOINT_CALLER_INFO
is enabled, pass the tracepoint's caller_info structure as parameter.
It should be straightforward to adapt the tracepoint callback prototypes within each
user within the Linux kernel tree. And for out-of-tree users, they have to adapt to
that kind of change already anyway.
Thoughts ?
Thanks,
Mathieu
--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com