[PATCHv3 0/3] tracing/rwmmio/arm64: Add support to trace register reads/writes

[PATCHv3 0/3] tracing/rwmmio/arm64: Add support to trace register reads/writes

[Sai Prakash Ranjan]

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/cover.1536430404.git.saiprakash.ranjan@codeaurora.org/
[2] https://lore.kernel.org/lkml/1604631386-178312-1-git-send-email-psodagud@codeaurora.org/

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

[PATCHv3 1/3] tracing: Add register read/write tracing support

[Sai Prakash Ranjan]

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 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 <psodagud@codeaurora.org>
[saiprakash: Rewrote commit msg and trace event field edits]
Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com>
---
 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

Re: [PATCHv3 1/3] tracing: Add register read/write tracing support

[Steven Rostedt]

On Tue, 9 Nov 2021 17:38:19 +0530
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 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 <psodagud@codeaurora.org>
> [saiprakash: Rewrote commit msg and trace event field edits]
> Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com>
> ---
>  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

Re: [PATCHv3 1/3] tracing: Add register read/write tracing support

[Sai Prakash Ranjan]

Hi Steve,

On 11/9/2021 7:24 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 17:38:19 +0530
> 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 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 <psodagud@codeaurora.org>
>> [saiprakash: Rewrote commit msg and trace event field edits]
>> Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com>
>> ---
>>   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

Re: [PATCHv3 1/3] tracing: Add register read/write tracing support

[kernel test robot]

[-- Attachment #1: Type: text/plain, Size: 10340 bytes --]

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 <lkp@intel.com>

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/kbuild-all@lists.01.org

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 69183 bytes --]

[PATCHv3 2/3] arm64/io: Add a header for mmio access instrumentation

[Sai Prakash Ranjan]

The new generic header mmio-instrumented.h will keep arch code clean
and separate from instrumented version which traces mmio register
accesses. This instrumented header is generic and can be used by other
architectures as well. Also add a generic flag (__DISABLE_TRACE_MMIO__)
which is used to disable MMIO tracing in nVHE and if required can be
used to disable tracing for specific drivers.

Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com>
---

I did look at Will's suggestion to move these logging to high level
accessors but that will miss several thousands of raw mmio accessors
being already used by several drivers.

$ git grep __raw_read* | wc -l
  2530
$ git grep __raw_write* | wc -l 
  3392

Also moving them to high level accessors like readl/writel would mean
requirement of separate logging for relaxed versions of those apis.

So in order to avoid all those extra hooks, I have kept the logging
in low-level arch code but separated out instrumentation to another
header as previously suggested by Will in initial version few years
back [1] to look at atomic instrumentation code.

[1] https://lore.kernel.org/lkml/20180807165713.GJ21809@arm.com/

---
 arch/arm64/include/asm/io.h       | 25 ++++-------
 arch/arm64/kvm/hyp/nvhe/Makefile  |  2 +-
 include/linux/mmio-instrumented.h | 70 +++++++++++++++++++++++++++++++
 3 files changed, 80 insertions(+), 17 deletions(-)
 create mode 100644 include/linux/mmio-instrumented.h

diff --git a/arch/arm64/include/asm/io.h b/arch/arm64/include/asm/io.h
index 7fd836bea7eb..a635aaaf81b9 100644
--- a/arch/arm64/include/asm/io.h
+++ b/arch/arm64/include/asm/io.h
@@ -10,6 +10,7 @@
 
 #include <linux/types.h>
 #include <linux/pgtable.h>
+#include <linux/mmio-instrumented.h>
 
 #include <asm/byteorder.h>
 #include <asm/barrier.h>
@@ -21,32 +22,27 @@
 /*
  * Generic IO read/write.  These perform native-endian accesses.
  */
-#define __raw_writeb __raw_writeb
-static inline void __raw_writeb(u8 val, volatile void __iomem *addr)
+static inline void arch_raw_writeb(u8 val, volatile void __iomem *addr)
 {
 	asm volatile("strb %w0, [%1]" : : "rZ" (val), "r" (addr));
 }
 
-#define __raw_writew __raw_writew
-static inline void __raw_writew(u16 val, volatile void __iomem *addr)
+static inline void arch_raw_writew(u16 val, volatile void __iomem *addr)
 {
 	asm volatile("strh %w0, [%1]" : : "rZ" (val), "r" (addr));
 }
 
-#define __raw_writel __raw_writel
-static __always_inline void __raw_writel(u32 val, volatile void __iomem *addr)
+static __always_inline void arch_raw_writel(u32 val, volatile void __iomem *addr)
 {
 	asm volatile("str %w0, [%1]" : : "rZ" (val), "r" (addr));
 }
 
-#define __raw_writeq __raw_writeq
-static inline void __raw_writeq(u64 val, volatile void __iomem *addr)
+static inline void arch_raw_writeq(u64 val, volatile void __iomem *addr)
 {
 	asm volatile("str %x0, [%1]" : : "rZ" (val), "r" (addr));
 }
 
-#define __raw_readb __raw_readb
-static inline u8 __raw_readb(const volatile void __iomem *addr)
+static inline u8 arch_raw_readb(const volatile void __iomem *addr)
 {
 	u8 val;
 	asm volatile(ALTERNATIVE("ldrb %w0, [%1]",
@@ -56,8 +52,7 @@ static inline u8 __raw_readb(const volatile void __iomem *addr)
 	return val;
 }
 
-#define __raw_readw __raw_readw
-static inline u16 __raw_readw(const volatile void __iomem *addr)
+static inline u16 arch_raw_readw(const volatile void __iomem *addr)
 {
 	u16 val;
 
@@ -68,8 +63,7 @@ static inline u16 __raw_readw(const volatile void __iomem *addr)
 	return val;
 }
 
-#define __raw_readl __raw_readl
-static __always_inline u32 __raw_readl(const volatile void __iomem *addr)
+static __always_inline u32 arch_raw_readl(const volatile void __iomem *addr)
 {
 	u32 val;
 	asm volatile(ALTERNATIVE("ldr %w0, [%1]",
@@ -79,8 +73,7 @@ static __always_inline u32 __raw_readl(const volatile void __iomem *addr)
 	return val;
 }
 
-#define __raw_readq __raw_readq
-static inline u64 __raw_readq(const volatile void __iomem *addr)
+static inline u64 arch_raw_readq(const volatile void __iomem *addr)
 {
 	u64 val;
 	asm volatile(ALTERNATIVE("ldr %0, [%1]",
diff --git a/arch/arm64/kvm/hyp/nvhe/Makefile b/arch/arm64/kvm/hyp/nvhe/Makefile
index c3c11974fa3b..ff56d2165ea9 100644
--- a/arch/arm64/kvm/hyp/nvhe/Makefile
+++ b/arch/arm64/kvm/hyp/nvhe/Makefile
@@ -4,7 +4,7 @@
 #
 
 asflags-y := -D__KVM_NVHE_HYPERVISOR__ -D__DISABLE_EXPORTS
-ccflags-y := -D__KVM_NVHE_HYPERVISOR__ -D__DISABLE_EXPORTS
+ccflags-y := -D__KVM_NVHE_HYPERVISOR__ -D__DISABLE_EXPORTS -D__DISABLE_TRACE_MMIO__
 
 hostprogs := gen-hyprel
 HOST_EXTRACFLAGS += -I$(objtree)/include
diff --git a/include/linux/mmio-instrumented.h b/include/linux/mmio-instrumented.h
new file mode 100644
index 000000000000..4304224f3be4
--- /dev/null
+++ b/include/linux/mmio-instrumented.h
@@ -0,0 +1,70 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2021 Qualcomm Innovation Center, Inc. All rights reserved.
+ */
+
+#ifndef _LINUX_MMIO_INSTRUMENTED_H
+#define _LINUX_MMIO_INSTRUMENTED_H
+
+#include <linux/tracepoint-defs.h>
+
+/*
+ * Tracepoint and MMIO logging symbols should not be visible at EL2(HYP) as
+ * there is no way to execute them and any such MMIO access from EL2 will
+ * explode instantly (Words of Marc Zyngier). So introduce a generic flag
+ * __DISABLE_TRACE_MMIO__ to disable MMIO tracing in nVHE and other drivers
+ * if required.
+ */
+#if IS_ENABLED(CONFIG_TRACE_MMIO_ACCESS) && !(defined(__DISABLE_TRACE_MMIO__))
+DECLARE_TRACEPOINT(rwmmio_write);
+DECLARE_TRACEPOINT(rwmmio_read);
+
+void log_write_mmio(const char *width, u64 val, volatile void __iomem *addr);
+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);	\
+	arch_raw_write##_l((v), _a);				\
+	})
+
+#define __raw_writeb(v, a)	__raw_write((v), a, b)
+#define __raw_writew(v, a)	__raw_write((v), a, w)
+#define __raw_writel(v, a)	__raw_write((v), a, l)
+#define __raw_writeq(v, a)	__raw_write((v), a, q)
+
+#define __raw_read(a, _l, _t)    ({				\
+	_t __a;							\
+	const volatile void __iomem *_a = (a);			\
+	if (tracepoint_enabled(rwmmio_read))			\
+		log_read_mmio(__stringify(read##_l), _a);	\
+	__a = arch_raw_read##_l(_a);				\
+	__a;							\
+	})
+
+#define __raw_readb(a)		__raw_read((a), b, u8)
+#define __raw_readw(a)		__raw_read((a), w, u16)
+#define __raw_readl(a)		__raw_read((a), l, u32)
+#define __raw_readq(a)		__raw_read((a), q, u64)
+
+#else
+
+#define __raw_writeb(v, a)	arch_raw_writeb(v, a)
+#define __raw_writew(v, a)	arch_raw_writew(v, a)
+#define __raw_writel(v, a)	arch_raw_writel(v, a)
+#define __raw_writeq(v, a)	arch_raw_writeq(v, a)
+
+#define __raw_readb(a)		arch_raw_readb(a)
+#define __raw_readw(a)		arch_raw_readw(a)
+#define __raw_readl(a)		arch_raw_readl(a)
+#define __raw_readq(a)		arch_raw_readq(a)
+
+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) {}
+
+#endif /* CONFIG_TRACE_MMIO_ACCESS */
+
+#endif /* _LINUX_MMIO_INSTRUMENTED_H */
-- 
2.29.0

[PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Sai Prakash Ranjan]

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 <jbaron@akamai.com>
Signed-off-by: Sai Prakash Ranjan <quic_saipraka@quicinc.com>
---
 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Steven Rostedt]

On Tue, 9 Nov 2021 17:38:21 +0530
Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Sai Prakash Ranjan]

Hi Steve,

On 11/9/2021 9:19 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 17:38:21 +0530
> Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Steven Rostedt]

On Tue, 9 Nov 2021 21:52:26 +0530
Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Sai Prakash Ranjan]

Hi Steve,

On 11/9/2021 10:29 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 21:52:26 +0530
> Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Steven Rostedt]

On Tue, 9 Nov 2021 23:00:11 +0530
Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Sai Prakash Ranjan]

On 11/9/2021 11:10 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 23:00:11 +0530
> Sai Prakash Ranjan <quic_saipraka@quicinc.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Jason Baron]

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 <quic_saipraka@quicinc.com> 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/20211105192637.2370737-9-jim.cromie@gmail.com/

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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Steven Rostedt]

On Tue, 9 Nov 2021 16:42:48 -0500
Jason Baron <jbaron@akamai.com> 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/20211105192637.2370737-9-jim.cromie@gmail.com/

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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Jason Baron]

On 11/9/21 4:51 PM, Steven Rostedt wrote:
> On Tue, 9 Nov 2021 16:42:48 -0500
> Jason Baron <jbaron@akamai.com> 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/20211105192637.2370737-9-jim.cromie@gmail.com/__;!!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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Steven Rostedt]

[ Hmm, should add Mathieu in on this discussion ]

On Tue, 9 Nov 2021 17:13:13 -0500
Jason Baron <jbaron@akamai.com> 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

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Jason Baron]

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 <jbaron@akamai.com> 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
> 

Re: [PATCHv3 3/3] dynamic_debug: Add a flag for dynamic event tracing

[Mathieu Desnoyers]

----- On Nov 9, 2021, at 5:28 PM, rostedt rostedt@goodmis.org wrote:

> [ Hmm, should add Mathieu in on this discussion ]
> 
> On Tue, 9 Nov 2021 17:13:13 -0500
> Jason Baron <jbaron@akamai.com> 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