[RFC PATCH v2 0/3] Register read/write tracing with dynamic debug and pstore

[RFC PATCH v2 0/3] Register read/write tracing with dynamic debug and pstore

[Sai Prakash Ranjan]

Hi,

This patch series adds a new tracing facility for register reads and writes called
Register Trace Buffer(RTB).

We also add pstore support through which we can save all register read/write logs into a
persistent ram buffer that can be dumped after reboot.

It can be used to determine from where register was read/written before unclocked
access or some kind of bus hang or an unexpected reset caused by some buggy driver
which happens a lot during initial development stages.

In addition to this, we 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 events and we will be interested only in specific drivers or subsystems
which we will be working on. Last few RTB entries will give us the hint for debugging.
With dynamic debug, we are also reducing the overhead of tracing considerably.

Also as a bonus, this tracing can be extended to include IRQ, printk, context switch
and lot other things with proper hooks. It can be very helpful for real case debug scenarios.

Below is a simple example of identifying cause for bus hang in qcom mdp tested on db410c.
This hang was intentionally introduced just to show the usecase of RTB.
The module used can be found here: https://github.com/saiprakash-ranjan/Bus-Hang which does
an unclocked access and will reset db410c and later logs can be viewed through pstore.

Note: I just copied bus_hang.c to drivers/soc/qcom and built it.

1) Set bootargs with dyndbg parameter as below:

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

2) Bus hang by reading below debugfs entry with bus_hang module.

   # cat /sys/kernel/debug/hang/bus_hang

3) After restart, we can find the cause in last entry i.e. (bus_hang_mdp+0x98/0xb0)

   # cat /sys/fs/pstore/rtb-ramoops-0
   [LOGK_WRITE] ts:1373101930  data:ffff00000cd065a4  <ffff00000867cb44>  qcom_smsm_probe+0x51c/0x668
   [LOGK_WRITE] ts:1373311878  data:ffff00000cd06608  <ffff00000867cb44>  qcom_smsm_probe+0x51c/0x668
   [LOGK_READ ] ts:18177142294  data:ffff00000ab85040 <ffff00000867cdc8>  bus_hang_mdp+0x98/0xb0

4) Offending register access found as below:

   # (gdb)
   # (gdb) list *(bus_hang_mdp+0x98)
   # 0xffff00000867cdc8 is in bus_hang_mdp (drivers/soc/qcom/bus_hang.c:10).
   # 5       static int bus_hang_mdp(void *data, u64 *val)
   # 6       {
   # 7               void *p = ioremap(0x01a01000, SZ_4K);
   # 8               unsigned int a;
   # 9
   # 10              a = __raw_readl((void *)((unsigned long)p + 0x40));  <----
   # 11
   # 12              *val = a;
   # 13
   # 14              return 0;
   # (gdb)

There will be a lot more real usecases where RTB can be used. Maybe we can test on other boards as well.

This trace module is based on RTB driver in CAF.
Link: https://source.codeaurora.org/quic/la/kernel/msm-4.9/tree/kernel/trace/msm_rtb.c

Patchwise one line description is given below:

Patch 1 provides the api called uncached_logk which is then called 
within dynamic_rtb for logging register accesses, i.e. (read/write{b,w,l,q})

Patch 2 adds the pstore support for displaying the logs after reset.

Patch 3 adds dynamic debug support to filter the register read/write{b,w,l,q} access.
Also this patch adds asm-generic/io-instrumented.h file for keeping instrumentation
away from arch code as suggested by Will Deacon.

v2:
 * Addressed Will's comment to keep instrumentation out of arch code and also
   remove duplicate code
 * Addressed Steven's comments regarding code cleanup
 * Fixed commit description to be more specific about register accesses i.e.,
   use read/write{b,l,w,q} instead of readl/writel since we will be tracing all

Sai Prakash Ranjan (3):
  tracing: Add support for logging data to uncached buffer
  pstore: Add register read/write{b,w,l,q} tracing support
  dynamic_debug: Add support for dynamic register trace

 .../bindings/reserved-memory/ramoops.txt      |   7 +-
 arch/arm64/include/asm/io.h                   |  26 ++--
 fs/pstore/Kconfig                             |  12 ++
 fs/pstore/Makefile                            |   1 +
 fs/pstore/inode.c                             |  71 ++++++++-
 fs/pstore/internal.h                          |   8 +
 fs/pstore/platform.c                          |   4 +
 fs/pstore/ram.c                               |  42 ++++-
 fs/pstore/rtb.c                               |  45 ++++++
 include/asm-generic/io-instrumented.h         |  32 ++++
 include/linux/dynamic_debug.h                 |  13 ++
 include/linux/pstore.h                        |   2 +
 include/linux/pstore_ram.h                    |   1 +
 include/linux/rtb.h                           |  31 ++++
 kernel/trace/Kconfig                          |   8 +
 kernel/trace/Makefile                         |   2 +
 kernel/trace/trace_rtb.c                      | 146 ++++++++++++++++++
 17 files changed, 430 insertions(+), 21 deletions(-)
 create mode 100644 fs/pstore/rtb.c
 create mode 100644 include/asm-generic/io-instrumented.h
 create mode 100644 include/linux/rtb.h
 create mode 100644 kernel/trace/trace_rtb.c

-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

[RFC PATCH v2 1/3] tracing: Add support for logging data to uncached buffer

[Sai Prakash Ranjan]

Add RTB trace support to write data to a small uncached buffer.
When a system reset occurs, valuable data may still be remaining
in the cache (e.g. last printks) and this data will probably
be lost, giving an incomplete picture of what the system was last
doing. By logging useful information to this uncached region
(e.g. read/write{b,w,l,q}, last printk), a better picture of what the
system was last doing can be obtained.

Dummy platform device is created to use dma api to allocate
uncached memory. Also initialize dma_mask and coherent_dma_mask after
commit 4d8bde883bfb ("OF: Don't set default coherent DMA mask").

We add an additional property called rtb-size in ramoops device
tree node for pstore RTB buffer size and use the same in the
trace module. DT documentation has been modified to include this.

Information logged in this buffer include log type(read/write{b,w,l,q}),
timestamp, extra data from the caller, caller ip and name.
This can be extented as needed to include more options(e.g. cpu)
for better debugging.

Also RTB panic notifier with high priority is used to make sure that RTB
is disabled right after a kernel panic so that log buffer could be
prevented from being flooded with some I/O operations.

This is based on RTB driver in CAF. Link below:
  * https://source.codeaurora.org/quic/la/kernel/msm-4.9
Modified to support pstore for viewing traces.

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 .../bindings/reserved-memory/ramoops.txt      |   7 +-
 include/linux/rtb.h                           |  24 +++
 kernel/trace/Kconfig                          |   7 +
 kernel/trace/Makefile                         |   2 +
 kernel/trace/trace_rtb.c                      | 143 ++++++++++++++++++
 5 files changed, 181 insertions(+), 2 deletions(-)
 create mode 100644 include/linux/rtb.h
 create mode 100644 kernel/trace/trace_rtb.c

diff --git a/Documentation/devicetree/bindings/reserved-memory/ramoops.txt b/Documentation/devicetree/bindings/reserved-memory/ramoops.txt
index 0eba562fe5c6..f99019d1119b 100644
--- a/Documentation/devicetree/bindings/reserved-memory/ramoops.txt
+++ b/Documentation/devicetree/bindings/reserved-memory/ramoops.txt
@@ -14,8 +14,8 @@ Any remaining space will be used for a circular buffer of oops and panic
 records.  These records have a configurable size, with a size of 0 indicating
 that they should be disabled.
 
-At least one of "record-size", "console-size", "ftrace-size", or "pmsg-size"
-must be set non-zero, but are otherwise optional as listed below.
+At least one of "record-size", "console-size", "ftrace-size", "pmsg-size" or
+"rtb-size" must be set non-zero, but are otherwise optional as listed below.
 
 
 Required properties:
@@ -42,6 +42,9 @@ Optional properties:
 - pmsg-size: size in bytes of log buffer reserved for userspace messages
   (defaults to 0: disabled)
 
+- rtb-size: size in bytes of log buffer reserved for RTB buffer traces.
+  (defaults to 0: disabled)
+
 - unbuffered: if present, use unbuffered mappings to map the reserved region
   (defaults to buffered mappings)
 
diff --git a/include/linux/rtb.h b/include/linux/rtb.h
new file mode 100644
index 000000000000..a969bd020466
--- /dev/null
+++ b/include/linux/rtb.h
@@ -0,0 +1,24 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#ifndef _RTB_H
+#define _RTB_H
+
+struct rtb_layout {
+	const char *log_type;
+	u32 idx;
+	u64 caller;
+	u64 data;
+	u64 timestamp;
+} __attribute__ ((__packed__));
+
+#if defined(CONFIG_RTB)
+void uncached_logk(const char *log_type, void *data);
+int rtb_init(void);
+void rtb_exit(void);
+#else
+static inline void uncached_logk(const char *log_type,
+				void *data) { }
+static inline int rtb_init(void) { return 0; }
+static inline void rtb_exit(void) { }
+#endif
+
+#endif /* _RTB_H */
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index c042a455afc6..fd46c7e0016f 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -774,6 +774,13 @@ config TRACING_EVENTS_GPIO
 	help
 	  Enable tracing events for gpio subsystem
 
+config RTB
+	bool "Register Trace Buffer"
+	help
+	  Add support for logging different events to a small uncached
+	  region. This is designed to aid in debugging reset cases where the
+	  caches may not be flushed before the target resets.
+
 endif # FTRACE
 
 endif # TRACING_SUPPORT
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 98d53b39a8ee..0b8167124354 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -78,4 +78,6 @@ obj-$(CONFIG_UPROBE_EVENTS) += trace_uprobe.o
 
 obj-$(CONFIG_TRACEPOINT_BENCHMARK) += trace_benchmark.o
 
+obj-$(CONFIG_RTB) += trace_rtb.o
+
 libftrace-y := ftrace.o
diff --git a/kernel/trace/trace_rtb.c b/kernel/trace/trace_rtb.c
new file mode 100644
index 000000000000..3e0a85e7b504
--- /dev/null
+++ b/kernel/trace/trace_rtb.c
@@ -0,0 +1,143 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2018 The Linux Foundation. All rights reserved.
+ */
+#include <linux/atomic.h>
+#include <linux/dma-mapping.h>
+#include <linux/export.h>
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/of_device.h>
+#include <linux/platform_device.h>
+#include <linux/rtb.h>
+#include <linux/sched/clock.h>
+
+static struct platform_device *rtb_dev;
+static atomic_t rtb_idx;
+
+struct rtb_state {
+	struct rtb_layout *rtb;
+	phys_addr_t phys;
+	unsigned int nentries;
+	unsigned int size;
+	int enabled;
+};
+
+/* RTB is enabled after pstore is registered, so let enabled flag be 0 */
+static struct rtb_state rtb;
+
+static int rtb_panic_notifier(struct notifier_block *this,
+					unsigned long event, void *ptr)
+{
+	rtb.enabled = 0;
+	return NOTIFY_DONE;
+}
+
+static struct notifier_block rtb_panic_blk = {
+	.notifier_call  = rtb_panic_notifier,
+	.priority = INT_MAX,
+};
+
+static void uncached_logk_pc_idx(const char *log_type, u64 caller,
+				u64 data, int idx)
+{
+	struct rtb_layout *start;
+
+	start = &rtb.rtb[idx & (rtb.nentries - 1)];
+
+	start->log_type = log_type;
+	start->caller = caller;
+	start->data = data;
+	start->timestamp = sched_clock();
+	/* Make sure data is written */
+	mb();
+}
+
+static int rtb_get_idx(void)
+{
+	int i, offset;
+
+	i = atomic_inc_return(&rtb_idx);
+	i--;
+
+	/* Check if index has wrapped around */
+	offset = (i & (rtb.nentries - 1)) -
+		 ((i - 1) & (rtb.nentries - 1));
+	if (offset < 0) {
+		i = atomic_inc_return(&rtb_idx);
+		i--;
+	}
+
+	return i;
+}
+
+noinline void uncached_logk(const char *log_type, void *data)
+{
+	int i;
+
+	if (!rtb.enabled)
+		return;
+
+	i = rtb_get_idx();
+	uncached_logk_pc_idx(log_type, (u64)(__builtin_return_address(0)),
+				(u64)(data), i);
+}
+EXPORT_SYMBOL(uncached_logk);
+
+int rtb_init(void)
+{
+	struct device_node *np;
+	u64 rtb_dmamask = DMA_BIT_MASK(32);
+	u32 size;
+	int ret;
+
+	np = of_find_node_by_name(NULL, "ramoops");
+	if (!np)
+		return -ENODEV;
+
+	ret = of_property_read_u32(np, "rtb-size", &size);
+	if (ret) {
+		of_node_put(np);
+		return ret;
+	}
+
+	rtb.size = size;
+
+	/* Create a dummy platform device to use dma api */
+	rtb_dev = platform_device_register_simple("rtb", -1, NULL, 0);
+	if (IS_ERR(rtb_dev))
+		return PTR_ERR(rtb_dev);
+
+	/* Initialize dma_mask and coherent_dma_mask to 32-bits */
+	rtb_dev->dev.dma_mask = &rtb_dmamask;
+	rtb_dev->dev.coherent_dma_mask = rtb_dmamask;
+
+	/*
+	 * The device is a dummy, so arch_setup_dma_ops
+	 * is not called, thus leaving the device with dummy DMA ops
+	 * which returns null in case of arm64.
+	 */
+	of_dma_configure(&rtb_dev->dev, NULL, true);
+	rtb.rtb = dma_alloc_coherent(&rtb_dev->dev, rtb.size,
+					&rtb.phys, GFP_KERNEL);
+	if (!rtb.rtb)
+		return -ENOMEM;
+
+	rtb.nentries = rtb.size / sizeof(struct rtb_layout);
+	/* Round this down to a power of 2 */
+	rtb.nentries = __rounddown_pow_of_two(rtb.nentries);
+
+	memset(rtb.rtb, 0, rtb.size);
+	atomic_set(&rtb_idx, 0);
+
+	atomic_notifier_chain_register(&panic_notifier_list,
+						&rtb_panic_blk);
+	rtb.enabled = 1;
+	return 0;
+}
+
+void rtb_exit(void)
+{
+	dma_free_coherent(&rtb_dev->dev, rtb.size, rtb.rtb, rtb.phys);
+	platform_device_unregister(rtb_dev);
+}
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

[RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[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:

 * 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 <saiprakash.ranjan@codeaurora.org>
---
 fs/pstore/Kconfig          | 12 +++++++
 fs/pstore/Makefile         |  1 +
 fs/pstore/inode.c          | 71 +++++++++++++++++++++++++++++++++++++-
 fs/pstore/internal.h       |  8 +++++
 fs/pstore/platform.c       |  4 +++
 fs/pstore/ram.c            | 42 ++++++++++++++++++++--
 fs/pstore/rtb.c            | 45 ++++++++++++++++++++++++
 include/linux/pstore.h     |  2 ++
 include/linux/pstore_ram.h |  1 +
 include/linux/rtb.h        |  7 ++++
 kernel/trace/trace_rtb.c   |  3 ++
 11 files changed, 193 insertions(+), 3 deletions(-)
 create mode 100644 fs/pstore/rtb.c

diff --git a/fs/pstore/Kconfig b/fs/pstore/Kconfig
index 503086f7f7c1..4f1ba1253dfd 100644
--- a/fs/pstore/Kconfig
+++ b/fs/pstore/Kconfig
@@ -124,6 +124,18 @@ config PSTORE_PMSG
 
 	  If unsure, say N.
 
+config PSTORE_RTB
+	bool "Log register operations like read/write"
+	depends on PSTORE && PSTORE!=m
+	depends on RTB
+	help
+	  When this option is enabled, rtb driver will log all register
+	  reads/writes into a persistent ram buffer that can be decoded
+	  and dumped after reboot through pstore filesystem. It can be used
+	  to debug readl/writel access.
+
+	  If unsure, say N.
+
 config PSTORE_FTRACE
 	bool "Persistent function tracer"
 	depends on PSTORE
diff --git a/fs/pstore/Makefile b/fs/pstore/Makefile
index 967b5891f325..c772c9420f57 100644
--- a/fs/pstore/Makefile
+++ b/fs/pstore/Makefile
@@ -9,6 +9,7 @@ pstore-objs += inode.o platform.o
 pstore-$(CONFIG_PSTORE_FTRACE)	+= ftrace.o
 
 pstore-$(CONFIG_PSTORE_PMSG)	+= pmsg.o
+pstore-$(CONFIG_PSTORE_RTB)	+= rtb.o
 
 ramoops-objs += ram.o ram_core.o
 obj-$(CONFIG_PSTORE_RAM)	+= ramoops.o
diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
index 5fcb845b9fec..467fb29bfd68 100644
--- a/fs/pstore/inode.c
+++ b/fs/pstore/inode.c
@@ -33,6 +33,7 @@
 #include <linux/sched.h>
 #include <linux/magic.h>
 #include <linux/pstore.h>
+#include <linux/rtb.h>
 #include <linux/slab.h>
 #include <linux/spinlock.h>
 #include <linux/uaccess.h>
@@ -57,6 +58,7 @@ struct pstore_ftrace_seq_data {
 };
 
 #define REC_SIZE sizeof(struct pstore_ftrace_record)
+#define REC_SIZE_RTB sizeof(struct rtb_layout)
 
 static void free_pstore_private(struct pstore_private *private)
 {
@@ -131,13 +133,73 @@ static const struct seq_operations pstore_ftrace_seq_ops = {
 	.show	= pstore_ftrace_seq_show,
 };
 
+static void *pstore_rtb_seq_start(struct seq_file *s, loff_t *pos)
+{
+	struct pstore_private *ps = s->private;
+	struct pstore_ftrace_seq_data *rdata;
+
+	rdata = kzalloc(sizeof(*rdata), GFP_KERNEL);
+	if (!rdata)
+		return NULL;
+
+	rdata->off = ps->total_size % REC_SIZE_RTB;
+	rdata->off += *pos * REC_SIZE_RTB;
+	if (rdata->off + REC_SIZE_RTB > ps->total_size) {
+		kfree(rdata);
+		return NULL;
+	}
+
+	return rdata;
+}
+
+static void pstore_rtb_seq_stop(struct seq_file *s, void *v)
+{
+	kfree(v);
+}
+
+static void *pstore_rtb_seq_next(struct seq_file *s, void *v, loff_t *pos)
+{
+	struct pstore_private *ps = s->private;
+	struct pstore_ftrace_seq_data *rdata = v;
+
+	rdata->off += REC_SIZE_RTB;
+	if (rdata->off + REC_SIZE_RTB > ps->total_size)
+		return NULL;
+
+	(*pos)++;
+	return rdata;
+}
+
+static int pstore_rtb_seq_show(struct seq_file *s, void *v)
+{
+	struct pstore_private *ps = s->private;
+	struct pstore_ftrace_seq_data *rdata = v;
+	struct rtb_layout *rec;
+
+	rec = (struct rtb_layout *)(ps->record->buf + rdata->off);
+
+	seq_printf(s, "[%-10s] ts:%llu  data:%llx  <%llx>  %pS\n",
+		   rec->log_type, rec->timestamp, rec->data,
+		   rec->caller, (void *)rec->caller);
+
+	return 0;
+}
+
+static const struct seq_operations pstore_rtb_seq_ops = {
+	.start	= pstore_rtb_seq_start,
+	.next	= pstore_rtb_seq_next,
+	.stop	= pstore_rtb_seq_stop,
+	.show	= pstore_rtb_seq_show,
+};
+
 static ssize_t pstore_file_read(struct file *file, char __user *userbuf,
 						size_t count, loff_t *ppos)
 {
 	struct seq_file *sf = file->private_data;
 	struct pstore_private *ps = sf->private;
 
-	if (ps->record->type == PSTORE_TYPE_FTRACE)
+	if (ps->record->type == PSTORE_TYPE_FTRACE ||
+			ps->record->type == PSTORE_TYPE_RTB)
 		return seq_read(file, userbuf, count, ppos);
 	return simple_read_from_buffer(userbuf, count, ppos,
 				       ps->record->buf, ps->total_size);
@@ -153,6 +215,9 @@ static int pstore_file_open(struct inode *inode, struct file *file)
 	if (ps->record->type == PSTORE_TYPE_FTRACE)
 		sops = &pstore_ftrace_seq_ops;
 
+	if (ps->record->type == PSTORE_TYPE_RTB)
+		sops = &pstore_rtb_seq_ops;
+
 	err = seq_open(file, sops);
 	if (err < 0)
 		return err;
@@ -373,6 +438,10 @@ int pstore_mkfile(struct dentry *root, struct pstore_record *record)
 		scnprintf(name, sizeof(name), "powerpc-opal-%s-%llu",
 			  record->psi->name, record->id);
 		break;
+	case PSTORE_TYPE_RTB:
+		scnprintf(name, sizeof(name), "rtb-%s-%llu",
+			  record->psi->name, record->id);
+		break;
 	case PSTORE_TYPE_UNKNOWN:
 		scnprintf(name, sizeof(name), "unknown-%s-%llu",
 			  record->psi->name, record->id);
diff --git a/fs/pstore/internal.h b/fs/pstore/internal.h
index fb767e28aeb2..a5498e8b89d2 100644
--- a/fs/pstore/internal.h
+++ b/fs/pstore/internal.h
@@ -25,6 +25,14 @@ static inline void pstore_register_pmsg(void) {}
 static inline void pstore_unregister_pmsg(void) {}
 #endif
 
+#ifdef CONFIG_PSTORE_RTB
+extern void pstore_register_rtb(void);
+extern void pstore_unregister_rtb(void);
+#else
+static inline void pstore_register_rtb(void) {}
+static inline void pstore_unregister_rtb(void) {}
+#endif
+
 extern struct pstore_info *psinfo;
 
 extern void	pstore_set_kmsg_bytes(int);
diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
index 15e99d5a681d..3473a7456585 100644
--- a/fs/pstore/platform.c
+++ b/fs/pstore/platform.c
@@ -589,6 +589,8 @@ int pstore_register(struct pstore_info *psi)
 		pstore_register_ftrace();
 	if (psi->flags & PSTORE_FLAGS_PMSG)
 		pstore_register_pmsg();
+	if (psi->flags & PSTORE_FLAGS_RTB)
+		pstore_register_rtb();
 
 	/* Start watching for new records, if desired. */
 	if (pstore_update_ms >= 0) {
@@ -618,6 +620,8 @@ void pstore_unregister(struct pstore_info *psi)
 	del_timer_sync(&pstore_timer);
 	flush_work(&pstore_work);
 
+	if (psi->flags & PSTORE_FLAGS_RTB)
+		pstore_unregister_rtb();
 	if (psi->flags & PSTORE_FLAGS_PMSG)
 		pstore_unregister_pmsg();
 	if (psi->flags & PSTORE_FLAGS_FTRACE)
diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
index bbd1e357c23d..79c00c7cf7b4 100644
--- a/fs/pstore/ram.c
+++ b/fs/pstore/ram.c
@@ -56,6 +56,10 @@ static ulong ramoops_pmsg_size = MIN_MEM_SIZE;
 module_param_named(pmsg_size, ramoops_pmsg_size, ulong, 0400);
 MODULE_PARM_DESC(pmsg_size, "size of user space message log");
 
+static ulong ramoops_rtb_size = MIN_MEM_SIZE;
+module_param_named(rtb_size, ramoops_rtb_size, ulong, 0400);
+MODULE_PARM_DESC(rtb_size, "size of register trace log");
+
 static unsigned long long mem_address;
 module_param_hw(mem_address, ullong, other, 0400);
 MODULE_PARM_DESC(mem_address,
@@ -88,6 +92,7 @@ struct ramoops_context {
 	struct persistent_ram_zone *cprz;	/* Console zone */
 	struct persistent_ram_zone **fprzs;	/* Ftrace zones */
 	struct persistent_ram_zone *mprz;	/* PMSG zone */
+	struct persistent_ram_zone *rprz;       /* RTB zone */
 	phys_addr_t phys_addr;
 	unsigned long size;
 	unsigned int memtype;
@@ -95,6 +100,7 @@ struct ramoops_context {
 	size_t console_size;
 	size_t ftrace_size;
 	size_t pmsg_size;
+	size_t rtb_size;
 	int dump_oops;
 	u32 flags;
 	struct persistent_ram_ecc_info ecc_info;
@@ -106,6 +112,7 @@ struct ramoops_context {
 	unsigned int max_ftrace_cnt;
 	unsigned int ftrace_read_cnt;
 	unsigned int pmsg_read_cnt;
+	unsigned int rtb_read_cnt;
 	struct pstore_info pstore;
 };
 
@@ -120,6 +127,7 @@ static int ramoops_pstore_open(struct pstore_info *psi)
 	cxt->console_read_cnt = 0;
 	cxt->ftrace_read_cnt = 0;
 	cxt->pmsg_read_cnt = 0;
+	cxt->rtb_read_cnt = 0;
 	return 0;
 }
 
@@ -282,6 +290,11 @@ static ssize_t ramoops_pstore_read(struct pstore_record *record)
 					   1, &record->id, &record->type,
 					   PSTORE_TYPE_PMSG, 0);
 
+	if (!prz_ok(prz))
+		prz = ramoops_get_next_prz(&cxt->rprz, &cxt->rtb_read_cnt,
+					   1, &record->id, &record->type,
+					   PSTORE_TYPE_RTB, 0);
+
 	/* ftrace is last since it may want to dynamically allocate memory. */
 	if (!prz_ok(prz)) {
 		if (!(cxt->flags & RAMOOPS_FLAG_FTRACE_PER_CPU)) {
@@ -404,6 +417,11 @@ static int notrace ramoops_pstore_write(struct pstore_record *record)
 	} else if (record->type == PSTORE_TYPE_PMSG) {
 		pr_warn_ratelimited("PMSG shouldn't call %s\n", __func__);
 		return -EINVAL;
+	} else if (record->type == PSTORE_TYPE_RTB) {
+		if (!cxt->rprz)
+			return -ENOMEM;
+		persistent_ram_write(cxt->rprz, record->buf, record->size);
+		return 0;
 	}
 
 	if (record->type != PSTORE_TYPE_DMESG)
@@ -483,6 +501,9 @@ static int ramoops_pstore_erase(struct pstore_record *record)
 	case PSTORE_TYPE_PMSG:
 		prz = cxt->mprz;
 		break;
+	case PSTORE_TYPE_RTB:
+		prz = cxt->rprz;
+		break;
 	default:
 		return -EINVAL;
 	}
@@ -701,6 +722,7 @@ static int ramoops_parse_dt(struct platform_device *pdev,
 	parse_size("console-size", pdata->console_size);
 	parse_size("ftrace-size", pdata->ftrace_size);
 	parse_size("pmsg-size", pdata->pmsg_size);
+	parse_size("rtb-size", pdata->rtb_size);
 	parse_size("ecc-size", pdata->ecc_info.ecc_size);
 	parse_size("flags", pdata->flags);
 
@@ -747,7 +769,8 @@ static int ramoops_probe(struct platform_device *pdev)
 	}
 
 	if (!pdata->mem_size || (!pdata->record_size && !pdata->console_size &&
-			!pdata->ftrace_size && !pdata->pmsg_size)) {
+			!pdata->ftrace_size && !pdata->pmsg_size &&
+			!pdata->rtb_size)) {
 		pr_err("The memory size and the record/console size must be "
 			"non-zero\n");
 		goto fail_out;
@@ -761,6 +784,8 @@ static int ramoops_probe(struct platform_device *pdev)
 		pdata->ftrace_size = rounddown_pow_of_two(pdata->ftrace_size);
 	if (pdata->pmsg_size && !is_power_of_2(pdata->pmsg_size))
 		pdata->pmsg_size = rounddown_pow_of_two(pdata->pmsg_size);
+	if (pdata->rtb_size && !is_power_of_2(pdata->rtb_size))
+		pdata->rtb_size = rounddown_pow_of_two(pdata->rtb_size);
 
 	cxt->size = pdata->mem_size;
 	cxt->phys_addr = pdata->mem_address;
@@ -769,6 +794,7 @@ static int ramoops_probe(struct platform_device *pdev)
 	cxt->console_size = pdata->console_size;
 	cxt->ftrace_size = pdata->ftrace_size;
 	cxt->pmsg_size = pdata->pmsg_size;
+	cxt->rtb_size = pdata->rtb_size;
 	cxt->dump_oops = pdata->dump_oops;
 	cxt->flags = pdata->flags;
 	cxt->ecc_info = pdata->ecc_info;
@@ -776,7 +802,7 @@ static int ramoops_probe(struct platform_device *pdev)
 	paddr = cxt->phys_addr;
 
 	dump_mem_sz = cxt->size - cxt->console_size - cxt->ftrace_size
-			- cxt->pmsg_size;
+			- cxt->pmsg_size - cxt->rtb_size;
 	err = ramoops_init_przs("dump", dev, cxt, &cxt->dprzs, &paddr,
 				dump_mem_sz, cxt->record_size,
 				&cxt->max_dump_cnt, 0, 0);
@@ -804,6 +830,11 @@ static int ramoops_probe(struct platform_device *pdev)
 	if (err)
 		goto fail_init_mprz;
 
+	err = ramoops_init_prz("rtb", dev, cxt, &cxt->rprz, &paddr,
+				cxt->rtb_size, 0);
+	if (err)
+		goto fail_init_rprz;
+
 	cxt->pstore.data = cxt;
 	/*
 	 * Console can handle any buffer size, so prefer LOG_LINE_MAX. If we
@@ -829,6 +860,8 @@ static int ramoops_probe(struct platform_device *pdev)
 		cxt->pstore.flags |= PSTORE_FLAGS_FTRACE;
 	if (cxt->pmsg_size)
 		cxt->pstore.flags |= PSTORE_FLAGS_PMSG;
+	if (cxt->rtb_size)
+		cxt->pstore.flags |= PSTORE_FLAGS_RTB;
 
 	err = pstore_register(&cxt->pstore);
 	if (err) {
@@ -846,6 +879,7 @@ static int ramoops_probe(struct platform_device *pdev)
 	dump_oops = pdata->dump_oops;
 	ramoops_console_size = pdata->console_size;
 	ramoops_pmsg_size = pdata->pmsg_size;
+	ramoops_rtb_size = pdata->rtb_size;
 	ramoops_ftrace_size = pdata->ftrace_size;
 
 	pr_info("attached 0x%lx@0x%llx, ecc: %d/%d\n",
@@ -858,6 +892,8 @@ static int ramoops_probe(struct platform_device *pdev)
 	kfree(cxt->pstore.buf);
 fail_clear:
 	cxt->pstore.bufsize = 0;
+	persistent_ram_free(cxt->rprz);
+fail_init_rprz:
 	persistent_ram_free(cxt->mprz);
 fail_init_mprz:
 fail_init_fprz:
@@ -877,6 +913,7 @@ static int ramoops_remove(struct platform_device *pdev)
 	kfree(cxt->pstore.buf);
 	cxt->pstore.bufsize = 0;
 
+	persistent_ram_free(cxt->rprz);
 	persistent_ram_free(cxt->mprz);
 	persistent_ram_free(cxt->cprz);
 	ramoops_free_przs(cxt);
@@ -918,6 +955,7 @@ static void ramoops_register_dummy(void)
 	dummy_data->console_size = ramoops_console_size;
 	dummy_data->ftrace_size = ramoops_ftrace_size;
 	dummy_data->pmsg_size = ramoops_pmsg_size;
+	dummy_data->rtb_size = ramoops_rtb_size;
 	dummy_data->dump_oops = dump_oops;
 	dummy_data->flags = RAMOOPS_FLAG_FTRACE_PER_CPU;
 
diff --git a/fs/pstore/rtb.c b/fs/pstore/rtb.c
new file mode 100644
index 000000000000..9fe159c38d64
--- /dev/null
+++ b/fs/pstore/rtb.c
@@ -0,0 +1,45 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2018 The Linux Foundation. All rights reserved.
+ */
+
+#include <linux/fs.h>
+#include <linux/irqflags.h>
+#include <linux/rtb.h>
+#include <linux/smp.h>
+
+#include "internal.h"
+
+void notrace pstore_rtb_call(struct rtb_layout *start)
+{
+	unsigned long flags;
+	struct pstore_record record = {
+		.type = PSTORE_TYPE_RTB,
+		.buf = (char *)start,
+		.size = sizeof(*start),
+		.psi = psinfo,
+	};
+
+	local_irq_save(flags);
+
+	psinfo->write(&record);
+
+	local_irq_restore(flags);
+}
+
+void pstore_register_rtb(void)
+{
+	int ret;
+
+	if (!psinfo->write)
+		return;
+
+	ret = rtb_init();
+	if (ret)
+		return;
+}
+
+void pstore_unregister_rtb(void)
+{
+	rtb_exit();
+}
diff --git a/include/linux/pstore.h b/include/linux/pstore.h
index a15bc4d48752..07ae7afe9d3a 100644
--- a/include/linux/pstore.h
+++ b/include/linux/pstore.h
@@ -44,6 +44,7 @@ enum pstore_type_id {
 	PSTORE_TYPE_PPC_COMMON	= 6,
 	PSTORE_TYPE_PMSG	= 7,
 	PSTORE_TYPE_PPC_OPAL	= 8,
+	PSTORE_TYPE_RTB		= 9,
 	PSTORE_TYPE_UNKNOWN	= 255
 };
 
@@ -193,6 +194,7 @@ struct pstore_info {
 #define PSTORE_FLAGS_CONSOLE	(1 << 1)
 #define PSTORE_FLAGS_FTRACE	(1 << 2)
 #define PSTORE_FLAGS_PMSG	(1 << 3)
+#define PSTORE_FLAGS_RTB	(1 << 4)
 
 extern int pstore_register(struct pstore_info *);
 extern void pstore_unregister(struct pstore_info *);
diff --git a/include/linux/pstore_ram.h b/include/linux/pstore_ram.h
index e6d226464838..81eee723f2bb 100644
--- a/include/linux/pstore_ram.h
+++ b/include/linux/pstore_ram.h
@@ -97,6 +97,7 @@ struct ramoops_platform_data {
 	unsigned long	console_size;
 	unsigned long	ftrace_size;
 	unsigned long	pmsg_size;
+	unsigned long	rtb_size;
 	int		dump_oops;
 	u32		flags;
 	struct persistent_ram_ecc_info ecc_info;
diff --git a/include/linux/rtb.h b/include/linux/rtb.h
index a969bd020466..169a77b4a565 100644
--- a/include/linux/rtb.h
+++ b/include/linux/rtb.h
@@ -21,4 +21,11 @@ static inline int rtb_init(void) { return 0; }
 static inline void rtb_exit(void) { }
 #endif
 
+#if defined(CONFIG_PSTORE_RTB)
+extern void pstore_rtb_call(struct rtb_layout *start);
+#else
+static inline void pstore_rtb_call(struct rtb_layout *start)
+{ }
+#endif
+
 #endif /* _RTB_H */
diff --git a/kernel/trace/trace_rtb.c b/kernel/trace/trace_rtb.c
index 3e0a85e7b504..26b87b3e6a03 100644
--- a/kernel/trace/trace_rtb.c
+++ b/kernel/trace/trace_rtb.c
@@ -51,6 +51,9 @@ static void uncached_logk_pc_idx(const char *log_type, u64 caller,
 	start->timestamp = sched_clock();
 	/* Make sure data is written */
 	mb();
+#if defined(CONFIG_PSTORE_RTB)
+	pstore_rtb_call(start);
+#endif
 }
 
 static int rtb_get_idx(void)
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

[RFC PATCH v2 3/3] dynamic_debug: Add support for dynamic register trace

[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 <saiprakash.ranjan@codeaurora.org>
---
 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

diff --git a/arch/arm64/include/asm/io.h b/arch/arm64/include/asm/io.h
index 35b2e50f17fb..aafd4b0be9f0 100644
--- a/arch/arm64/include/asm/io.h
+++ b/arch/arm64/include/asm/io.h
@@ -22,6 +22,7 @@
 #ifdef __KERNEL__
 
 #include <linux/types.h>
+#include <linux/rtb.h>
 
 #include <asm/byteorder.h>
 #include <asm/barrier.h>
@@ -36,32 +37,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 inline void __raw_writel(u32 val, volatile void __iomem *addr)
+static 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]",
@@ -71,8 +67,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;
 
@@ -83,8 +78,7 @@ static inline u16 __raw_readw(const volatile void __iomem *addr)
 	return val;
 }
 
-#define __raw_readl __raw_readl
-static inline u32 __raw_readl(const volatile void __iomem *addr)
+static inline u32 arch_raw_readl(const volatile void __iomem *addr)
 {
 	u32 val;
 	asm volatile(ALTERNATIVE("ldr %w0, [%1]",
@@ -94,8 +88,7 @@ static 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]",
@@ -193,6 +186,7 @@ extern void __iomem *ioremap_cache(phys_addr_t phys_addr, size_t size);
 #define iowrite32be(v,p)	({ __iowmb(); __raw_writel((__force __u32)cpu_to_be32(v), p); })
 #define iowrite64be(v,p)	({ __iowmb(); __raw_writeq((__force __u64)cpu_to_be64(v), p); })
 
+#include <asm-generic/io-instrumented.h>
 #include <asm-generic/io.h>
 
 /*
diff --git a/include/asm-generic/io-instrumented.h b/include/asm-generic/io-instrumented.h
new file mode 100644
index 000000000000..ce273742b98c
--- /dev/null
+++ b/include/asm-generic/io-instrumented.h
@@ -0,0 +1,32 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
+#define _ASM_GENERIC_IO_INSTRUMENTED_H
+
+#include <linux/dynamic_debug.h>
+
+#define __raw_write(v, a, _t) ({			\
+	volatile void __iomem *_a = (a);		\
+	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)
+#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);\
+	dynamic_rtb("LOGK_READ", (void __force *)(_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)
+
+#endif
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 2fd8006153c3..946b60f48401 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -155,6 +155,18 @@ do {								\
 			       buf, len, ascii);		\
 } while (0)
 
+#if defined(CONFIG_RTB)
+#define dynamic_rtb(log_type, data)				\
+do {								\
+	DEFINE_DYNAMIC_DEBUG_METADATA(descriptor,		\
+		__builtin_constant_p(log_type) ? log_type : "rtb");\
+	if (DYNAMIC_DEBUG_BRANCH(descriptor))			\
+		uncached_logk(log_type, data);			\
+} while (0)
+#else
+#define dynamic_rtb(log_type, data)
+#endif
+
 #else
 
 #include <linux/string.h>
@@ -181,6 +193,7 @@ static inline int ddebug_dyndbg_module_param_cb(char *param, char *val,
 	do { if (0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); } while (0)
 #define dynamic_dev_dbg(dev, fmt, ...)					\
 	do { if (0) dev_printk(KERN_DEBUG, dev, fmt, ##__VA_ARGS__); } while (0)
+#define dynamic_rtb(log_type, data)
 #endif
 
 #endif
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index fd46c7e0016f..59f01091b5ee 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -776,6 +776,7 @@ config TRACING_EVENTS_GPIO
 
 config RTB
 	bool "Register Trace Buffer"
+	depends on DYNAMIC_DEBUG
 	help
 	  Add support for logging different events to a small uncached
 	  region. This is designed to aid in debugging reset cases where the
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Kees Cook]

On Fri, Aug 24, 2018 at 7:45 AM, Sai Prakash Ranjan
<saiprakash.ranjan@codeaurora.org> wrote:
> 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 <saiprakash.ranjan@codeaurora.org>

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.

-Kees

-- 
Kees Cook
Pixel Security

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Sai Prakash Ranjan]

On 8/24/2018 8:59 PM, Kees Cook wrote:
> On Fri, Aug 24, 2018 at 7:45 AM, Sai Prakash Ranjan
> <saiprakash.ranjan@codeaurora.org> wrote:
>> 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 <saiprakash.ranjan@codeaurora.org>
> 
> 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.

Thanks,
Sai Prakash

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Steven Rostedt]

On Sat, 25 Aug 2018 12:54:07 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:


> 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.


> 
> 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).

> 
> * 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.


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


mmiotrace is separate because it faults on writes so that we can
capture any reads and writes to the system that a binary driver does.

-- Steve

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Sai Prakash Ranjan]

On 8/27/2018 9:45 PM, Steven Rostedt wrote:
> On Sat, 25 Aug 2018 12:54:07 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
> 
>> 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.
> 
>

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

>>
>> 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?

>>
>> * 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.
> 
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?

- Sai Prakash

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Steven Rostedt]

On Tue, 28 Aug 2018 18:47:33 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> On 8/27/2018 9:45 PM, Steven Rostedt wrote:
> > On Sat, 25 Aug 2018 12:54:07 +0530
> > Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> > 
> >   
> >> 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.
> > 
> >  
> 
> Thank you very much for the information Steven. Ok so we can get 
> function parameters with pt_regs.

Yes.

> 
> >>
> >> 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?

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@devbox)

> 
> >>
> >> * 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.
> >   
> 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?

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.

-- Steve

Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Sai Prakash Ranjan]

On 8/28/2018 9:32 PM, Steven Rostedt wrote:
> On Tue, 28 Aug 2018 18:47:33 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
>> On 8/27/2018 9:45 PM, Steven Rostedt wrote:
>>> On Sat, 25 Aug 2018 12:54:07 +0530
>>> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>>    
>>>> 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.
>>>
>>>   
>>
>> Thank you very much for the information Steven. Ok so we can get
>> function parameters with pt_regs.
> 
> Yes.
> 
>>
>>>>
>>>> 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?
> 
> 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@devbox)
> 
Cool, thanks for the link.
>>
>>>>
>>>> * 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.
>>>    
>> 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?
> 
> 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.
> 

Wow, thank you so much for the detailed explanation, it helps a lot. I 
will try to use this and post next version soon.

- Sai Prakash

Re: [RFC PATCH v2 3/3] dynamic_debug: Add support for dynamic register trace

[Will Deacon]

On Fri, Aug 24, 2018 at 08:15:27PM +0530, Sai Prakash Ranjan wrote:
> 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 <saiprakash.ranjan@codeaurora.org>
> ---
>  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
> 
> diff --git a/arch/arm64/include/asm/io.h b/arch/arm64/include/asm/io.h
> index 35b2e50f17fb..aafd4b0be9f0 100644
> --- a/arch/arm64/include/asm/io.h
> +++ b/arch/arm64/include/asm/io.h

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

> diff --git a/include/asm-generic/io-instrumented.h b/include/asm-generic/io-instrumented.h
> new file mode 100644
> index 000000000000..ce273742b98c
> --- /dev/null
> +++ b/include/asm-generic/io-instrumented.h
> @@ -0,0 +1,32 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
> +#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?

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

> +	dynamic_rtb("LOGK_READ", (void __force *)(_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)

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!

Will

Re: [RFC PATCH v2 3/3] dynamic_debug: Add support for dynamic register trace

[Sai Prakash Ranjan]

On 9/6/2018 3:35 PM, Will Deacon wrote:
> On Fri, Aug 24, 2018 at 08:15:27PM +0530, Sai Prakash Ranjan wrote:
>> 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 <saiprakash.ranjan@codeaurora.org>
>> ---
>>   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
>>
>> diff --git a/arch/arm64/include/asm/io.h b/arch/arm64/include/asm/io.h
>> index 35b2e50f17fb..aafd4b0be9f0 100644
>> --- a/arch/arm64/include/asm/io.h
>> +++ b/arch/arm64/include/asm/io.h
> 
> The arm64 bits look fine to me, but please can you split them into a
> separate patch?
> 

Thanks for the review. Sure, I will split them into separate patch in 
next post. I have got the tracepoints working now as Steven suggested, 
will upload them soon.

>> diff --git a/include/asm-generic/io-instrumented.h b/include/asm-generic/io-instrumented.h
>> new file mode 100644
>> index 000000000000..ce273742b98c
>> --- /dev/null
>> +++ b/include/asm-generic/io-instrumented.h
>> @@ -0,0 +1,32 @@
>> +/* SPDX-License-Identifier: GPL-2.0 */
>> +
>> +#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
>> +#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?
> 

To avoid 100's of compilation warnings like below. Also wanted the 
parameters of functions like "iowrite32" to be passed to 
arch_raw_{read,write}() as is.

./include/asm-generic/io.h: In function ‘iowrite32’:
./include/asm-generic/io-instrumented.h:8:21: warning: initialization 
discards ‘volatile’ qualifier from pointer target type 
[-Wdiscarded-qualifiers]
   void __iomem *_a = (a);    \
                      ^
./include/asm-generic/io-instrumented.h:15:28: note: in expansion of 
macro ‘__raw_write’
  #define __raw_writel(v, a) __raw_write((v), a, l)
                             ^~~~~~~~~~~
./arch/arm64/include/asm/io.h:118:36: note: in expansion of macro 
‘__raw_writel’
  #define writel_relaxed(v,c) ((void)__raw_writel((__force 
u32)cpu_to_le32(v),(c)))
                                     ^~~~~~~~~~~~
./arch/arm64/include/asm/io.h:133:36: note: in expansion of macro 
‘writel_relaxed’
  #define writel(v,c)  ({ __iowmb(); writel_relaxed((v),(c)); })
                                     ^~~~~~~~~~~~~~
./include/asm-generic/io.h:745:2: note: in expansion of macro ‘writel’
   writel(value, addr);
   ^~~~~~

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

Same as above.

>> +	dynamic_rtb("LOGK_READ", (void __force *)(_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)
> 
> 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!
> 
Sorry for the confusion, I will fix it and have _l for both 
_raw_{read,write}.

Thanks,
Sai Prakash