Register read/write tracing with dynamic debug and pstore

read/write{b,w,l,q} are typically used for reading from memory mapped registers, which can cause hangs if accessed unclocked. Tracing these events can help in debugging various issues faced during initial development.

We log this trace information in persistent ram buffer which can be viewed after reset.

We use pstore_rtb_call() to write the RTB log to pstore. RTB buffer size is taken from ramoops dt node with additional property called rtb-size.

For reading the trace after mounting pstore, rtb-ramoops entry can be seen in /sys/fs/pstore/ as in below sample output.

Sample output of tracing register reads/writes in drivers:

 # mount -t pstore pstore /sys/fs/pstore
 # tail /sys/fs/pstore/rtb-ramoops-0
 [LOGK_READ ] ts:36468476204  data:ffff00000800d0fc  <ffff0000084e9ee0>  gic_check_gicv2+0x58/0x60
 [LOGK_WRITE] ts:36468477715  data:ffff00000800d000  <ffff0000084e9fac>  gic_cpu_if_up+0xc4/0x110
 [LOGK_READ ] ts:36468478548  data:ffff00000800d000  <ffff0000084e9fd8>  gic_cpu_if_up+0xf0/0x110
 [LOGK_WRITE] ts:36468480319  data:ffff00000800d000  <ffff0000084e9fac>  gic_cpu_if_up+0xc4/0x110
 [LOGK_READ ] ts:36468481048  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
 [LOGK_WRITE] ts:36468482923  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128
 [LOGK_READ ] ts:36468483184  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
 [LOGK_WRITE] ts:36468485215  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128
 [LOGK_READ ] ts:36468486309  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
 [LOGK_WRITE] ts:36468488236  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128

Output has below 5 fields:

* Log type, Timestamp, Data from caller which is the address of read/write{b,w,l,q}, Caller ip and Caller name.

Signed-off-by Sai Prakash Ranjan <[email protected]>

Quoted 32 lines · Sai Prakash Ranjan

read/write{b,w,l,q} are typically used for reading from memory mapped registers, which can cause hangs if accessed unclocked. Tracing these events can help in debugging various issues faced during initial development.

We log this trace information in persistent ram buffer which can be viewed after reset.

We use pstore_rtb_call() to write the RTB log to pstore. RTB buffer size is taken from ramoops dt node with additional property called rtb-size.

For reading the trace after mounting pstore, rtb-ramoops entry can be seen in /sys/fs/pstore/ as in below sample output.

Sample output of tracing register reads/writes in drivers:

  # mount -t pstore pstore /sys/fs/pstore
  # tail /sys/fs/pstore/rtb-ramoops-0
  [LOGK_READ ] ts:36468476204  data:ffff00000800d0fc  <ffff0000084e9ee0>  gic_check_gicv2+0x58/0x60
  [LOGK_WRITE] ts:36468477715  data:ffff00000800d000  <ffff0000084e9fac>  gic_cpu_if_up+0xc4/0x110
  [LOGK_READ ] ts:36468478548  data:ffff00000800d000  <ffff0000084e9fd8>  gic_cpu_if_up+0xf0/0x110
  [LOGK_WRITE] ts:36468480319  data:ffff00000800d000  <ffff0000084e9fac>  gic_cpu_if_up+0xc4/0x110
  [LOGK_READ ] ts:36468481048  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
  [LOGK_WRITE] ts:36468482923  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128
  [LOGK_READ ] ts:36468483184  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
  [LOGK_WRITE] ts:36468485215  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128
  [LOGK_READ ] ts:36468486309  data:ffff00000800d00c  <ffff000008081a34>  gic_handle_irq+0xac/0x128
  [LOGK_WRITE] ts:36468488236  data:ffff00000800d010  <ffff000008081aac>  gic_handle_irq+0x124/0x128

Output has below 5 fields:

Quoted 4 lines

* Log type, Timestamp, Data from caller which is the address of read/write{b,w,l,q}, Caller ip and Caller name.

Signed-off-by Sai Prakash Ranjan <[email protected]>

As this is a tracing-like method, could this instead be added to ftrace? That would mean it could reuse all the ftrace tools and you'd get pstore storage for free.

Ftrace does not trace __raw{read,write}{b,l,w,q}() functions. I am not sure why and how it is filtered out because I do not see any notrace flag in those functions, maybe that whole directory is filtered out. So adding this functionality to ftrace would mean removing the notrace for these functions i.e., something like using __raw{read,write}{b,l,w,q}() as the available filter functions. Also pstore ftrace does not filter functions to trace I suppose?

Coming to the reason as to why it would be good to keep this separate from ftrace would be:
* Ftrace can get ip and parent ip, but suppose we need extra data (field data) as in above sample output we would not be able to get through ftrace.

* Although this patch is for tracing register read/write, we can easily add more functionality since we have dynamic_rtb api which can be hooked to functions and start tracing events(IRQ, Context ID) something similar to tracepoints.
Initially thought of having tracepoints for logging register read/write but I do not know if we can export tracepoint data to pstore since the main usecase is to debug unknown resets and hangs.

* This can be something similar to mmiotrace in x86 and kept seperate from function tracer.

Quoted 7 lines · On Sat, 25 Aug 2018 12:54:07 +0530 Sai Prakash Ranjan…

Ftrace does not trace __raw{read,write}{b,l,w,q}() functions. I am not sure why and how it is filtered out because I do not see any notrace flag in those functions, maybe that whole directory is filtered out. So adding this functionality to ftrace would mean removing the notrace for these functions i.e., something like using __raw{read,write}{b,l,w,q}() as the available filter functions. Also pstore ftrace does not filter functions to trace I suppose?

It's not traced because it is inlined. Simply make the __raw_read function a normal function and it will be traced. And then you could use ftrace to read the function.

If this has to be per arch, you can register your callback with the REGS flags, and pt_regs will be passed to your callback function you attached to __raw_read*() as if you inserted a break point at that location, and you can get any reg data you want there.

Quoted 5 lines

Coming to the reason as to why it would be good to keep this separate from ftrace would be:
* Ftrace can get ip and parent ip, but suppose we need extra data (field data) as in above sample output we would not be able to get through ftrace.

As mentioned above, you can get regs (and ftrace is being expanded now to get parameters of functions).

Quoted 8 lines

* Although this patch is for tracing register read/write, we can easily add more functionality since we have dynamic_rtb api which can be hooked to functions and start tracing events(IRQ, Context ID) something similar to tracepoints.
Initially thought of having tracepoints for logging register read/write but I do not know if we can export tracepoint data to pstore since the main usecase is to debug unknown resets and hangs.

I don't know why not? We have read/write tracepoints for read/write_msr() calls in x86.

Anything can add a hook to the callback of the tracepoints, and use that infrastructure instead of creating yet another dynamic code modification infrastructure.

Quoted 12 lines · Steven Rostedt

Quoted 7 lines · On Sat, 25 Aug 2018 12:54:07 +0530 Sai Prakash Ranjan…

Ftrace does not trace __raw{read,write}{b,l,w,q}() functions. I am not sure why and how it is filtered out because I do not see any notrace flag in those functions, maybe that whole directory is filtered out. So adding this functionality to ftrace would mean removing the notrace for these functions i.e., something like using __raw{read,write}{b,l,w,q}() as the available filter functions. Also pstore ftrace does not filter functions to trace I suppose?

Quoted 10 lines

It's not traced because it is inlined. Simply make the __raw_read function a normal function and it will be traced. And then you could use ftrace to read the function.

If this has to be per arch, you can register your callback with the REGS flags, and pt_regs will be passed to your callback function you attached to __raw_read*() as if you inserted a break point at that location, and you can get any reg data you want there.

Thank you very much for the information Steven. Ok so we can get function parameters with pt_regs.

Quoted 10 lines

Quoted 6 lines

Coming to the reason as to why it would be good to keep this separate from ftrace would be:
* Ftrace can get ip and parent ip, but suppose we need extra data (field data) as in above sample output we would not be able to get through ftrace.

As mentioned above, you can get regs (and ftrace is being expanded now to get parameters of functions).

You mean there is another way to get parameters other than regs?

Quoted 10 lines

Quoted 9 lines

* Although this patch is for tracing register read/write, we can easily add more functionality since we have dynamic_rtb api which can be hooked to functions and start tracing events(IRQ, Context ID) something similar to tracepoints.
Initially thought of having tracepoints for logging register read/write but I do not know if we can export tracepoint data to pstore since the main usecase is to debug unknown resets and hangs.

Quoted 7 lines

I don't know why not? We have read/write tracepoints for read/write_msr() calls in x86.

Anything can add a hook to the callback of the tracepoints, and use that infrastructure instead of creating yet another dynamic code modification infrastructure.

Thanks for pointing out to read/write_msr, I checked it and was able to implement something similar for arm64. But still can we export tracepoint data to pstore because we need to debug reset cases and for that pstore is of real importance?. If so then it would be great to have various events logged into pstore which can be a lot of help for debugging.

Also with the current dynamic filtering of read/write(PATCH 3/3), it is a lot easier to filter register read/write since we use dynamic debug framework which provides file, function and line level filtering capacity. Maybe if we can add something like this to trace events it would be better?

Quoted 24 lines · On Tue, 28 Aug 2018 18:47:33 +0530 Sai Prakash Ranjan…

Quoted 12 lines · Steven Rostedt

Quoted 7 lines · On Sat, 25 Aug 2018 12:54:07 +0530 Sai Prakash Ranjan…

Ftrace does not trace __raw{read,write}{b,l,w,q}() functions. I am not sure why and how it is filtered out because I do not see any notrace flag in those functions, maybe that whole directory is filtered out. So adding this functionality to ftrace would mean removing the notrace for these functions i.e., something like using __raw{read,write}{b,l,w,q}() as the available filter functions. Also pstore ftrace does not filter functions to trace I suppose?

Quoted 10 lines

It's not traced because it is inlined. Simply make the __raw_read function a normal function and it will be traced. And then you could use ftrace to read the function.

If this has to be per arch, you can register your callback with the REGS flags, and pt_regs will be passed to your callback function you attached to __raw_read*() as if you inserted a break point at that location, and you can get any reg data you want there.

Quoted 2 lines

Thank you very much for the information Steven. Ok so we can get function parameters with pt_regs.

Yes.

Quoted 10 lines

Quoted 10 lines

Quoted 6 lines

Coming to the reason as to why it would be good to keep this separate from ftrace would be:
* Ftrace can get ip and parent ip, but suppose we need extra data (field data) as in above sample output we would not be able to get through ftrace.

As mentioned above, you can get regs (and ftrace is being expanded now to get parameters of functions).

Quoted 1 line

You mean there is another way to get parameters other than regs?

No, but you could register a callback function to be called when a function is hit, and the pt_regs are passed to it. We are working on getting parameters from the pt_regs (see this patch:
http://lkml.kernel.org/r/152465885737.26224.2822487520472783854.stgit at devbox)

Quoted 23 lines

Quoted 10 lines

Quoted 9 lines

* Although this patch is for tracing register read/write, we can easily add more functionality since we have dynamic_rtb api which can be hooked to functions and start tracing events(IRQ, Context ID) something similar to tracepoints.
Initially thought of having tracepoints for logging register read/write but I do not know if we can export tracepoint data to pstore since the main usecase is to debug unknown resets and hangs.

Quoted 7 lines

I don't know why not? We have read/write tracepoints for read/write_msr() calls in x86.

Anything can add a hook to the callback of the tracepoints, and use that infrastructure instead of creating yet another dynamic code modification infrastructure.

Thanks for pointing out to read/write_msr, I checked it and was able to implement something similar for arm64. But still can we export tracepoint data to pstore because we need to debug reset cases and for that pstore is of real importance?. If so then it would be great to have various events logged into pstore which can be a lot of help for debugging.

Quoted 5 lines

Also with the current dynamic filtering of read/write(PATCH 3/3), it is a lot easier to filter register read/write since we use dynamic debug framework which provides file, function and line level filtering capacity. Maybe if we can add something like this to trace events it would be better?

I would recommend using the tracepoint infrastructure. Note, tracepoints and trace events are two different things. Trace events use tracepoints, and you use trace events to create tracepoints, thus they are tightly coupled. But once a tracepoint exists, anything can connect to them without needing to use the trace event.

Let's look at the read_msr trace event. Because it is in a header, to avoid "include hell" we open code some of it:

static inline unsigned long long native_read_msr(unsigned int msr)

{
	unsigned long long val;

	val = __rdmsr(msr);

	if (msr_tracepoint_active(__tracepoint_read_msr))
		do_trace_read_msr(msr, val, 0);

	return val;
}

Where:

#ifdef CONFIG_TRACEPOINTS
#define msr_tracepoint_active(t) static_key_false(&(t).key) #else
#define msr_tracepoint_active(t) false
#endif

We have to open code the access to the tracepoint.key because msr.h is used in a lot of critical headers, we couldn't use the normal tracepoint.h header here.

The "static_key_false()" is a jump label that is just a nop. When the static_key is enabled, the nop is converted to a static "jmp" to the code that calls "do_trace_read_msr()". This is a function call to a function defined in msr.c (where we can do proper includes), and all that does is call the tracepoint "trace_read_msr()", which is also a static key that, when enabled, will iterate over a list of functions it should call with the defined parameters (msr, val, failed).

When defining the trace event for "read_msr", it creates the tracepoint "trace_read_msr()" and we place it in this do_trace_read_msr() function. The TRACE_EVENT() macros creates everything that is needed to connect the trace event "read_msr" to the tracepoint "trace_read_msr()", and you can enable this via the tracefs subsystem or via perf.

But you can also add your own hook to that tracepoint. If you have code that does:

register_trace_read_msr(func, data);

The "func" gets called when trace_read_msr() is hit. Thus you could have:

static void my_func(void *data, unsigned msr, u64 val, int failed)

{
	struct my_struct *my_data = data;

	do_something_with(my_data, msr, val, failed);
}

{
	struct my_struct *my_data;

	my_data = kzalloc(sizeof(*my_data)), GFP_KERNEL);

	register_trace_read_msr(my_func, my_data);
}

And then your function "my_func" will be called with any data you registered with it (you may register "NULL" if you don't need to pass in data), and it will also get the parameters passed to trace_read_msr()

If you want to have you "my_func" record into pstore, then it will happen at runtime, and if the system resets, you have your data where you want it.

include/asm-generic/io-instrumented.h new file +0 -0

new file mode 100644
index 000000000000..ce273742b98c

Quoted 35 lines · Sai Prakash Ranjan

Introduce dynamic debug filtering mechanism to register tracing as dynamic_rtb() which will reduce a lot of overhead otherwise of tracing all the register reads/writes in all files.

Now we can just specify the file name or any wildcard pattern as any other dynamic debug facility in bootargs and dynamic rtb will just trace them and the output can be seen in pstore.

TODO: Now we use same 'p' flag but will add a separate flag for register trace later.

Also add asm-generic/io-instrumented.h file for instrumentation of IO operations such as read/write{b,w,l,q} as per Will's suggestion to not touch arch code and let core generate instrumentation.
This can be extended to arm as well later for tracing.

Example for tracing all register reads/writes in drivers/soc/qcom/* below:

# dyndbg="file drivers/soc/qcom/* +p" in bootargs

   # reboot -f
   # mount -t pstore pstore /sys/fs/pstore
   # cat /sys/fs/pstore/rtb-ramoops-0
     [LOGK_WRITE] ts:1373030419  data:ffff00000d5065a4  <ffff00000867cb44>  qcom_smsm_probe+0x51c/0x668
     [LOGK_WRITE] ts:1373360576  data:ffff00000d506608  <ffff00000867cb44>  qcom_smsm_probe+0x51c/0x668

Signed-off-by Sai Prakash Ranjan <[email protected]>

---
  arch/arm64/include/asm/io.h           | 26 +++++++++-------------
  include/asm-generic/io-instrumented.h | 32 +++++++++++++++++++++++++++
  include/linux/dynamic_debug.h         | 13 +++++++++++
  kernel/trace/Kconfig                  |  1 +
  4 files changed, 56 insertions(+), 16 deletions(-)

create mode 100644 include/asm-generic/io-instrumented.h

arch/arm64/include/asm/io.h

Quoted 4 lines

arch/arm64/include/asm/io.h +0 -0

index 35b2e50f17fb..aafd4b0be9f0 100644

The arm64 bits look fine to me, but please can you split them into a separate patch?

Quoted 9 lines

include/asm-generic/io-instrumented.h new file +3 -0

new file mode 100644
index 000000000000..ce273742b98c
@@ -0,0 +1,32 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H

include/asm-generic/io-instrumented.h line 9

Quoted 6 lines

include/asm-generic/io-instrumented.h new file +6 -0

+#define _ASM_GENERIC_IO_INSTRUMENTED_H
+
+#include <linux/dynamic_debug.h>
+
+#define __raw_write(v, a, _t) ({			\
+	volatile void __iomem *_a = (a);		\

Does this actually need to be volatile?

Quoted 6 lines

include/asm-generic/io-instrumented.h new file +6 -0

+	dynamic_rtb("LOGK_WRITE", (void __force *)(_a));\
+	arch_raw_write##_t((v), _a);			\
+	})
+
+#define __raw_writeb(v, a)	__raw_write((v), a, b)
+#define __raw_writew(v, a)	__raw_write((v), a, w)

include/asm-generic/io-instrumented.h line 21

Quoted 6 lines

include/asm-generic/io-instrumented.h new file +6 -0

+#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 = (const volatile void __iomem *)(a);\

Again, can't this just be void __iomem * ?

Quoted 4 lines

include/asm-generic/io-instrumented.h new file +4 -0

+	dynamic_rtb("LOGK_READ", (void __force *)(_a));			\
+	__a = arch_raw_read##_l(_a);					\
+	__a;								\
+	})

include/asm-generic/io-instrumented.h line 30

Quoted 5 lines

include/asm-generic/io-instrumented.h new file +5 -0

+
+#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)

I find the way you've defined the __raw_{read,write} macros quite confusing. They both have an _t parameter, but it's totally unrelated between the two!