[PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Sai Prakash Ranjan]

Hi,

This patch series adds Event tracing support to pstore and is continuation
to the RFC patch introduced to add a new tracing facility for register
accesses called Register Trace Buffer(RTB). Since we decided to not introduce
a separate framework to trace register accesses and use existing framework
like tracepoints, I have moved from RFC. Details of the RFC in link below:

Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/

MSR tracing example given by Steven was helpful in using tracepoints for
register accesses instead of using separate trace. But just having these
IO traces would not help much unless we could have them in some persistent
ram buffer for debugging 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. By analyzing the last few entries of this buffer,
we could identify the register access which is causing the issue.

But again, adding pstore support for just one such event would be unacceptable.
Instead, add pstore support for all events since event tracing is widely used
across the kernel to debug variety of issues and adding this support would be
really useful for such purposes.

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. Currently only register
access trace for arm64 will have this support but this could be expanded later
to other events also if required.

First example below shows the use of tracing events with pstore support. Here
we trace sched events:

  # trace_event=sched tp_pstore in command line
  # reboot -f
  # mount -t pstore pstore /sys/fs/pstore/
  # tail /sys/fs/pstore/event-ramoops-0
  sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=10 next_prio=120
  sched_switch: prev_comm=rcu_preempt prev_pid=10 prev_prio=120 prev_state=R+ ==> next_comm=swapper/1 next_pid=0 next_prio=120
  sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=002
  sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=002
  sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=11 next_prio=120
  sched_switch: prev_comm=rcu_sched prev_pid=11 prev_prio=120 prev_state=R+ ==> next_comm=swapper/2 next_pid=0 next_prio=120
  sched_waking: comm=reboot pid=1867 prio=120 target_cpu=000
  sched_wakeup: comm=reboot pid=1867 prio=120 target_cpu=000
  sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=reboot next_pid=1867 next_prio=120

We can get more details for debugging as we can see from the above pstore
output.

Below is the second example for identifying the root cause of bus hang in
qcom mdp tested on db410c. This hang was intentionally introduced just to
show the usecase of tracing with pstore. The module used can be found here:
 https://github.com/saiprakash-ranjan/Bus-Hang
This does an unclocked access and will reset db410c and later logs can be
viewed through pstore. Here we manually specify the path to trace in kernel
command line.

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

1) Set command line with dyndbg, trace_event and tp_pstore parameter as below:

   # dyndbg="file drivers/soc/qcom/* +e" trace_event=io tp_pstore

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+0xa4/0xb8)

   # cat /sys/fs/pstore/event-ramoops-0
   io_write: type=writel cpu=0 ts:1423426774 data=0xffff00000d5065a4 caller=qcom_smsm_probe+0x52c/0x678
   io_write: type=writel cpu=0 ts:1423649847 data=0xffff00000d506608 caller=qcom_smsm_probe+0x52c/0x678
   io_read: type=readl cpu=1 ts:53095994171 data=0xffff00000a51d040 caller=bus_hang_mdp+0xa4/0xb8

4) Offending register access found as below:

   # (gdb)
   # (gdb) list *(bus_hang_mdp+0xa4)
   # 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)

Patchwise oneline description is given below:

Patch 1 adds event-size property to dt-bindings of ramoops.

Patch 2 adds generic event tracing support to pstore.

Patch 3 adds tp_pstore cmdline to have tracepoints go to pstore.

Patch 4 adds tracepoint for register accesses, i.e. for (read/write{b,w,l,q}).

Patch 5 adds new header for instrumentation of io operations.

Patch 6 adds new flag for dynamic event tracing.

Sai Prakash Ranjan (6):
  dt-bindings: ramoops: Add event-size property
  pstore: Add event tracing support
  tracing: Add tp_pstore cmdline to have tracepoints go to pstore
  arm64/io: Add tracepoint for register accesses
  arm64/io: Add header for instrumentation of io operations
  dynamic_debug: Add flag for dynamic event tracing

 .../admin-guide/kernel-parameters.txt         | 21 ++++++
 .../bindings/reserved-memory/ramoops.txt      |  7 +-
 arch/arm64/include/asm/io.h                   | 25 +++----
 arch/arm64/kernel/io.c                        | 22 ++++++
 fs/pstore/Kconfig                             |  2 +-
 fs/pstore/ftrace.c                            | 55 +++++++++++++++
 fs/pstore/inode.c                             |  4 ++
 fs/pstore/ram.c                               | 44 +++++++++++-
 include/asm-generic/io-instrumented.h         | 69 ++++++++++++++++++
 include/asm-generic/io-trace.h                | 70 +++++++++++++++++++
 include/linux/dynamic_debug.h                 |  1 +
 include/linux/ftrace.h                        |  6 +-
 include/linux/pstore.h                        |  2 +
 include/linux/pstore_ram.h                    |  1 +
 kernel/sysctl.c                               |  7 ++
 kernel/trace/Kconfig                          | 22 +++++-
 kernel/trace/trace.c                          | 51 ++++++++++++++
 kernel/trace/trace.h                          |  7 ++
 lib/dynamic_debug.c                           |  1 +
 19 files changed, 393 insertions(+), 24 deletions(-)
 create mode 100644 include/asm-generic/io-instrumented.h
 create mode 100644 include/asm-generic/io-trace.h

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

[PATCH 1/6] dt-bindings: ramoops: Add event-size property

[Sai Prakash Ranjan]

Add an optional property called event-size to reserve
log buffer for trace events.

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 .../devicetree/bindings/reserved-memory/ramoops.txt        | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/Documentation/devicetree/bindings/reserved-memory/ramoops.txt b/Documentation/devicetree/bindings/reserved-memory/ramoops.txt
index 0eba562fe5c6..4f835ef65635 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", "event-size", "ftrace-size", or
+"pmsg-size" must be set non-zero, but are otherwise optional as listed below.
 
 
 Required properties:
@@ -36,6 +36,9 @@ Optional properties:
 - console-size: size in bytes of log buffer reserved for kernel messages
   (defaults to 0: disabled)
 
+- event-size: size in bytes of log buffer reserved for trace events
+  (defaults to 0: disabled)
+
 - ftrace-size: size in bytes of log buffer reserved for function tracing and
   profiling (defaults to 0: disabled)
 
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [PATCH 1/6] dt-bindings: ramoops: Add event-size property

[Sai Prakash Ranjan]

On 9/17/2018 11:15 AM, Rob Herring wrote:
> On Sun,  9 Sep 2018 01:57:02 +0530, Sai Prakash Ranjan wrote:
>> Add an optional property called event-size to reserve
>> log buffer for trace events.
>>
>> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
>> ---
>>   .../devicetree/bindings/reserved-memory/ramoops.txt        | 7 +++++--
>>   1 file changed, 5 insertions(+), 2 deletions(-)
>>
> 
> Reviewed-by: Rob Herring <robh@kernel.org>
> 

Thanks a lot for the review Rob.

- Sai

[PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

Currently pstore has function trace support which can be
used to get the function call chain with limited data.
Event tracing has extra data which is useful to debug wide
variety of issues and is heavily used across the kernel.

Adding this support to pstore can be very helpful to debug
different subsystems since almost all of them have trace
events already available. And also it is useful to debug
unknown resets or crashes since we can get lot more info
from event tracing by viewing the last occurred events.

High frequency tracepoints such as sched and irq has also
been tested. This implementation is similar to "tp_printk"
command line feature of ftrace by Steven.

For example, sample pstore output of tracing sched events
after reboot:

  # mount -t pstore pstore /sys/fs/pstore/
  # tail /sys/fs/pstore/event-ramoops-0
  sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=10 next_prio=120
  sched_switch: prev_comm=rcu_preempt prev_pid=10 prev_prio=120 prev_state=R+ ==> next_comm=swapper/1 next_pid=0 next_prio=120
  sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=002
  sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=002
  sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=11 next_prio=120
  sched_switch: prev_comm=rcu_sched prev_pid=11 prev_prio=120 prev_state=R+ ==> next_comm=swapper/2 next_pid=0 next_prio=120
  sched_waking: comm=reboot pid=1867 prio=120 target_cpu=000
  sched_wakeup: comm=reboot pid=1867 prio=120 target_cpu=000
  sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=reboot next_pid=1867 next_prio=120

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 fs/pstore/Kconfig          |  2 +-
 fs/pstore/ftrace.c         | 55 ++++++++++++++++++++++++++++++++++++++
 fs/pstore/inode.c          |  4 +++
 fs/pstore/ram.c            | 44 +++++++++++++++++++++++++++---
 include/linux/pstore.h     |  2 ++
 include/linux/pstore_ram.h |  1 +
 6 files changed, 104 insertions(+), 4 deletions(-)

diff --git a/fs/pstore/Kconfig b/fs/pstore/Kconfig
index 503086f7f7c1..6fe087b13a51 100644
--- a/fs/pstore/Kconfig
+++ b/fs/pstore/Kconfig
@@ -126,7 +126,7 @@ config PSTORE_PMSG
 
 config PSTORE_FTRACE
 	bool "Persistent function tracer"
-	depends on PSTORE
+	depends on PSTORE && PSTORE!=m
 	depends on FUNCTION_TRACER
 	depends on DEBUG_FS
 	help
diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
index 06aab07b6bb7..d47dc93ac098 100644
--- a/fs/pstore/ftrace.c
+++ b/fs/pstore/ftrace.c
@@ -24,6 +24,8 @@
 #include <linux/debugfs.h>
 #include <linux/err.h>
 #include <linux/cache.h>
+#include <linux/slab.h>
+#include <linux/trace_events.h>
 #include <asm/barrier.h>
 #include "internal.h"
 
@@ -62,6 +64,59 @@ static struct ftrace_ops pstore_ftrace_ops __read_mostly = {
 	.func	= pstore_ftrace_call,
 };
 
+void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
+{
+	struct trace_iterator *iter;
+	struct trace_seq *s;
+	struct trace_event_call *event_call;
+	struct pstore_record record;
+	struct trace_event *event;
+	struct seq_buf *seq;
+	unsigned long flags;
+
+	if (!psinfo)
+		return;
+
+	if (unlikely(oops_in_progress))
+		return;
+
+	pstore_record_init(&record, psinfo);
+	record.type = PSTORE_TYPE_EVENT;
+
+	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
+	if (!iter)
+		return;
+
+	event_call = fbuffer->trace_file->event_call;
+	if (!event_call || !event_call->event.funcs ||
+	    !event_call->event.funcs->trace)
+		goto fail_event;
+
+	event = &fbuffer->trace_file->event_call->event;
+
+	spin_lock_irqsave(&psinfo->buf_lock, flags);
+
+	trace_seq_init(&iter->seq);
+	iter->ent = fbuffer->entry;
+	event_call->event.funcs->trace(iter, 0, event);
+	trace_seq_putc(&iter->seq, 0);
+
+	if (seq->size > psinfo->bufsize)
+		seq->size = psinfo->bufsize;
+
+	s = &iter->seq;
+	seq = &s->seq;
+
+	record.buf = (char *)(seq->buffer);
+	record.size = seq->len;
+	psinfo->write(&record);
+
+	spin_unlock_irqrestore(&psinfo->buf_lock, flags);
+
+fail_event:
+	kfree(iter);
+}
+
 static DEFINE_MUTEX(pstore_ftrace_lock);
 static bool pstore_ftrace_enabled;
 
diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
index 5fcb845b9fec..f099152abbbd 100644
--- a/fs/pstore/inode.c
+++ b/fs/pstore/inode.c
@@ -345,6 +345,10 @@ int pstore_mkfile(struct dentry *root, struct pstore_record *record)
 		scnprintf(name, sizeof(name), "console-%s-%llu",
 			  record->psi->name, record->id);
 		break;
+	case PSTORE_TYPE_EVENT:
+		scnprintf(name, sizeof(name), "event-%s-%llu",
+			  record->psi->name, record->id);
+		break;
 	case PSTORE_TYPE_FTRACE:
 		scnprintf(name, sizeof(name), "ftrace-%s-%llu",
 			  record->psi->name, record->id);
diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
index bbd1e357c23d..f60d41c0309e 100644
--- a/fs/pstore/ram.c
+++ b/fs/pstore/ram.c
@@ -48,6 +48,10 @@ static ulong ramoops_console_size = MIN_MEM_SIZE;
 module_param_named(console_size, ramoops_console_size, ulong, 0400);
 MODULE_PARM_DESC(console_size, "size of kernel console log");
 
+static ulong ramoops_event_size = MIN_MEM_SIZE;
+module_param_named(event_size, ramoops_event_size, ulong, 0400);
+MODULE_PARM_DESC(event_size, "size of event log");
+
 static ulong ramoops_ftrace_size = MIN_MEM_SIZE;
 module_param_named(ftrace_size, ramoops_ftrace_size, ulong, 0400);
 MODULE_PARM_DESC(ftrace_size, "size of ftrace log");
@@ -86,6 +90,7 @@ MODULE_PARM_DESC(ramoops_ecc,
 struct ramoops_context {
 	struct persistent_ram_zone **dprzs;	/* Oops dump zones */
 	struct persistent_ram_zone *cprz;	/* Console zone */
+	struct persistent_ram_zone *eprz;       /* Event zone */
 	struct persistent_ram_zone **fprzs;	/* Ftrace zones */
 	struct persistent_ram_zone *mprz;	/* PMSG zone */
 	phys_addr_t phys_addr;
@@ -93,6 +98,7 @@ struct ramoops_context {
 	unsigned int memtype;
 	size_t record_size;
 	size_t console_size;
+	size_t event_size;
 	size_t ftrace_size;
 	size_t pmsg_size;
 	int dump_oops;
@@ -103,6 +109,7 @@ struct ramoops_context {
 	/* _read_cnt need clear on ramoops_pstore_open */
 	unsigned int dump_read_cnt;
 	unsigned int console_read_cnt;
+	unsigned int event_read_cnt;
 	unsigned int max_ftrace_cnt;
 	unsigned int ftrace_read_cnt;
 	unsigned int pmsg_read_cnt;
@@ -118,6 +125,7 @@ static int ramoops_pstore_open(struct pstore_info *psi)
 
 	cxt->dump_read_cnt = 0;
 	cxt->console_read_cnt = 0;
+	cxt->event_read_cnt = 0;
 	cxt->ftrace_read_cnt = 0;
 	cxt->pmsg_read_cnt = 0;
 	return 0;
@@ -277,6 +285,11 @@ static ssize_t ramoops_pstore_read(struct pstore_record *record)
 					   1, &record->id, &record->type,
 					   PSTORE_TYPE_CONSOLE, 0);
 
+	if (!prz_ok(prz))
+		prz = ramoops_get_next_prz(&cxt->eprz, &cxt->event_read_cnt,
+					   1, &record->id, &record->type,
+					   PSTORE_TYPE_EVENT, 0);
+
 	if (!prz_ok(prz))
 		prz = ramoops_get_next_prz(&cxt->mprz, &cxt->pmsg_read_cnt,
 					   1, &record->id, &record->type,
@@ -385,6 +398,11 @@ static int notrace ramoops_pstore_write(struct pstore_record *record)
 			return -ENOMEM;
 		persistent_ram_write(cxt->cprz, record->buf, record->size);
 		return 0;
+	} else if (record->type == PSTORE_TYPE_EVENT) {
+		if (!cxt->eprz)
+			return -ENOMEM;
+		persistent_ram_write(cxt->eprz, record->buf, record->size);
+		return 0;
 	} else if (record->type == PSTORE_TYPE_FTRACE) {
 		int zonenum;
 
@@ -475,6 +493,9 @@ static int ramoops_pstore_erase(struct pstore_record *record)
 	case PSTORE_TYPE_CONSOLE:
 		prz = cxt->cprz;
 		break;
+	case PSTORE_TYPE_EVENT:
+		prz = cxt->eprz;
+		break;
 	case PSTORE_TYPE_FTRACE:
 		if (record->id >= cxt->max_ftrace_cnt)
 			return -EINVAL;
@@ -699,6 +720,7 @@ static int ramoops_parse_dt(struct platform_device *pdev,
 
 	parse_size("record-size", pdata->record_size);
 	parse_size("console-size", pdata->console_size);
+	parse_size("event-size", pdata->event_size);
 	parse_size("ftrace-size", pdata->ftrace_size);
 	parse_size("pmsg-size", pdata->pmsg_size);
 	parse_size("ecc-size", pdata->ecc_info.ecc_size);
@@ -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->event_size && !pdata->ftrace_size &&
+			!pdata->pmsg_size)) {
 		pr_err("The memory size and the record/console size must be "
 			"non-zero\n");
 		goto fail_out;
@@ -757,6 +780,8 @@ static int ramoops_probe(struct platform_device *pdev)
 		pdata->record_size = rounddown_pow_of_two(pdata->record_size);
 	if (pdata->console_size && !is_power_of_2(pdata->console_size))
 		pdata->console_size = rounddown_pow_of_two(pdata->console_size);
+	if (pdata->event_size && !is_power_of_2(pdata->event_size))
+		pdata->event_size = rounddown_pow_of_two(pdata->event_size);
 	if (pdata->ftrace_size && !is_power_of_2(pdata->ftrace_size))
 		pdata->ftrace_size = rounddown_pow_of_two(pdata->ftrace_size);
 	if (pdata->pmsg_size && !is_power_of_2(pdata->pmsg_size))
@@ -767,6 +792,7 @@ static int ramoops_probe(struct platform_device *pdev)
 	cxt->memtype = pdata->mem_type;
 	cxt->record_size = pdata->record_size;
 	cxt->console_size = pdata->console_size;
+	cxt->event_size = pdata->event_size;
 	cxt->ftrace_size = pdata->ftrace_size;
 	cxt->pmsg_size = pdata->pmsg_size;
 	cxt->dump_oops = pdata->dump_oops;
@@ -775,8 +801,8 @@ 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;
+	dump_mem_sz = cxt->size - cxt->console_size - cxt->event_size
+			- cxt->ftrace_size - cxt->pmsg_size;
 	err = ramoops_init_przs("dump", dev, cxt, &cxt->dprzs, &paddr,
 				dump_mem_sz, cxt->record_size,
 				&cxt->max_dump_cnt, 0, 0);
@@ -788,6 +814,11 @@ static int ramoops_probe(struct platform_device *pdev)
 	if (err)
 		goto fail_init_cprz;
 
+	err = ramoops_init_prz("event", dev, cxt, &cxt->eprz, &paddr,
+			       cxt->event_size, 0);
+	if (err)
+		goto fail_init_eprz;
+
 	cxt->max_ftrace_cnt = (cxt->flags & RAMOOPS_FLAG_FTRACE_PER_CPU)
 				? nr_cpu_ids
 				: 1;
@@ -825,6 +856,8 @@ static int ramoops_probe(struct platform_device *pdev)
 	cxt->pstore.flags = PSTORE_FLAGS_DMESG;
 	if (cxt->console_size)
 		cxt->pstore.flags |= PSTORE_FLAGS_CONSOLE;
+	if (cxt->event_size)
+		cxt->pstore.flags |= PSTORE_FLAGS_EVENT;
 	if (cxt->ftrace_size)
 		cxt->pstore.flags |= PSTORE_FLAGS_FTRACE;
 	if (cxt->pmsg_size)
@@ -845,6 +878,7 @@ static int ramoops_probe(struct platform_device *pdev)
 	record_size = pdata->record_size;
 	dump_oops = pdata->dump_oops;
 	ramoops_console_size = pdata->console_size;
+	ramoops_event_size = pdata->event_size;
 	ramoops_pmsg_size = pdata->pmsg_size;
 	ramoops_ftrace_size = pdata->ftrace_size;
 
@@ -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->eprz);
+fail_init_eprz:
 	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->eprz);
 	persistent_ram_free(cxt->mprz);
 	persistent_ram_free(cxt->cprz);
 	ramoops_free_przs(cxt);
@@ -916,6 +953,7 @@ static void ramoops_register_dummy(void)
 	dummy_data->mem_type = mem_type;
 	dummy_data->record_size = record_size;
 	dummy_data->console_size = ramoops_console_size;
+	dummy_data->event_size = ramoops_event_size;
 	dummy_data->ftrace_size = ramoops_ftrace_size;
 	dummy_data->pmsg_size = ramoops_pmsg_size;
 	dummy_data->dump_oops = dump_oops;
diff --git a/include/linux/pstore.h b/include/linux/pstore.h
index a15bc4d48752..c31bb9567b4a 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_EVENT	= 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_EVENT	(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..f01055c6cc40 100644
--- a/include/linux/pstore_ram.h
+++ b/include/linux/pstore_ram.h
@@ -95,6 +95,7 @@ struct ramoops_platform_data {
 	unsigned int	mem_type;
 	unsigned long	record_size;
 	unsigned long	console_size;
+	unsigned long	event_size;
 	unsigned long	ftrace_size;
 	unsigned long	pmsg_size;
 	int		dump_oops;
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
> +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
> +{
> +	struct trace_iterator *iter;
> +	struct trace_seq *s;
> +	struct trace_event_call *event_call;
> +	struct pstore_record record;
> +	struct trace_event *event;
> +	struct seq_buf *seq;
> +	unsigned long flags;
> +
> +	if (!psinfo)
> +		return;
> +
> +	if (unlikely(oops_in_progress))
> +		return;
> +
> +	pstore_record_init(&record, psinfo);
> +	record.type = PSTORE_TYPE_EVENT;
> +
> +	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> +	if (!iter)
> +		return;
> +
> +	event_call = fbuffer->trace_file->event_call;
> +	if (!event_call || !event_call->event.funcs ||
> +	    !event_call->event.funcs->trace)
> +		goto fail_event;
> +
> +	event = &fbuffer->trace_file->event_call->event;
> +
> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
> +
> +	trace_seq_init(&iter->seq);
> +	iter->ent = fbuffer->entry;
> +	event_call->event.funcs->trace(iter, 0, event);
> +	trace_seq_putc(&iter->seq, 0);
> +
> +	if (seq->size > psinfo->bufsize)
> +		seq->size = psinfo->bufsize;
> +
> +	s = &iter->seq;
> +	seq = &s->seq;
> +
> +	record.buf = (char *)(seq->buffer);
> +	record.size = seq->len;
> +	psinfo->write(&record);
> +
> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> +
> +fail_event:
> +	kfree(iter);
> +}
> +
> 

When tracing sched events on sdm845 mtp, I hit below bug repeatedly.
Seems like pstore_event_call can be called in atomic context.
I will respin the below fix in next version of the patch.
Reviews on other parts would be appreciated, thanks.

diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
index d47dc93ac098..a497cf782ee8 100644
--- a/fs/pstore/ftrace.c
+++ b/fs/pstore/ftrace.c
@@ -73,6 +73,7 @@ void notrace pstore_event_call(struct 
trace_event_buffer *fbuffer)
         struct trace_event *event;
         struct seq_buf *seq;
         unsigned long flags;
+       gfp_t gfpflags;

         if (!psinfo)
                 return;
@@ -83,7 +84,9 @@ void notrace pstore_event_call(struct 
trace_event_buffer *fbuffer)
         pstore_record_init(&record, psinfo);
         record.type = PSTORE_TYPE_EVENT;

-       iter = kmalloc(sizeof(*iter), GFP_KERNEL);
+       gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC : 
GFP_KERNEL;
+
+       iter = kmalloc(sizeof(*iter), gfpflags);
         if (!iter)
                 return;

Backtrace:

[    0.433204] clocksource: Switched to clocksource arch_sys_counter
[    0.440035] pstore: using zlib compression
[    0.444265] BUG: sleeping function called from invalid context at 
/mnt/host/source/src/third_party/kernel/v4.14/mm/page_alloc.c:4134
[    0.444268] in_atomic(): 1, irqs_disabled(): 128, pid: 1, name: swapper/0
[    0.444277] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 4.14.65 #19
[    0.444286] Call trace:
[    0.444303] [<ffffff800808a91c>] dump_backtrace+0x0/0x254
[    0.444309] [<ffffff800808ab90>] show_stack+0x20/0x28
[    0.444320] [<ffffff8008913794>] dump_stack+0x90/0xb0
[    0.444329] [<ffffff80080d9080>] ___might_sleep+0x110/0x128
[    0.444332] [<ffffff80080d9110>] __might_sleep+0x78/0x88
[    0.444343] [<ffffff80081b83c4>] __alloc_pages_nodemask+0xe4/0xef4
[    0.444351] [<ffffff80081da1ac>] kmalloc_order+0x34/0x5c
[    0.444355] [<ffffff80081da210>] kmalloc_order_trace+0x3c/0x10c
[    0.444366] [<ffffff800832b5fc>] pstore_event_call+0x64/0x148
[    0.444374] [<ffffff800817b754>] trace_event_buffer_commit+0x230/0x25c
[    0.444379] [<ffffff80080d774c>] 
trace_event_raw_event_sched_stat_runtime+0x78/0xc8
[    0.444385] [<ffffff80080e4d5c>] update_curr+0x184/0x208
[    0.444388] [<ffffff80080e5fc0>] task_tick_fair+0x58/0x478
[    0.444394] [<ffffff80080dd834>] scheduler_tick+0x78/0xb4
[    0.444404] [<ffffff800811d714>] update_process_times+0x48/0x5c
[    0.444411] [<ffffff800812e198>] tick_sched_handle.isra.9+0x58/0x6c
[    0.444415] [<ffffff800812e1f4>] tick_sched_timer+0x48/0x84
[    0.444420] [<ffffff800811e218>] __hrtimer_run_queues+0x1f0/0x31c
[    0.444423] [<ffffff800811eb78>] hrtimer_interrupt+0xa8/0x1c8
[    0.444435] [<ffffff8008720bc8>] arch_timer_handler_phys+0x3c/0x48
[    0.444443] [<ffffff800810a750>] handle_percpu_devid_irq+0x124/0x27c
[    0.444448] [<ffffff8008104e48>] generic_handle_irq+0x30/0x44
[    0.444452] [<ffffff80081054dc>] __handle_domain_irq+0x90/0xbc
[    0.444457] [<ffffff8008081250>] gic_handle_irq+0x144/0x1ac
[    0.444460] Exception stack(0xffffff800805b5f0 to 0xffffff800805b730)
[    0.444465] b5e0:                                   0000000000000040 
ffffffc0fb2d8000
[    0.444468] b600: 00000040f7046000 ffffffffffffffff 0000000000000000 
0000000000000000
[    0.444472] b620: ffffffc0fb288f00 0720072007200720 0720072007200720 
0720072007200720
[    0.444475] b640: 0720072007200720 0720072007200720 0720072007200720 
0720072007200720
[    0.444479] b660: 0720072007200720 0000000000000010 0000000000000003 
0000000000004600
[    0.444482] b680: 000000000000000c ffffff8009152000 ffffff8009192000 
000000000000002e
[    0.444485] b6a0: ffffff8009192458 0000000000000000 0000000000000000 
ffffff8009031410
[    0.444490] b6c0: ffffff8008ec7018 ffffff8009031410 ffffff8009031000 
ffffff800805b730
[    0.444495] b6e0: ffffff80081030d4 ffffff800805b730 ffffff80081030dc 
0000000060c00049
[    0.444498] b700: 0000000000000000 ffffff80090916a0 ffffffffffffffff 
ffffff8008ec7018
[    0.444502] b720: ffffff800805b730 ffffff80081030dc
[    0.444506] [<ffffff8008082a30>] el1_irq+0xb0/0x124
[    0.444510] [<ffffff80081030dc>] console_unlock+0x27c/0x4e0
[    0.444512] [<ffffff80081035b0>] vprintk_emit+0x270/0x290
[    0.444515] [<ffffff80081037c0>] vprintk_default+0x7c/0x84
[    0.444518] [<ffffff8008104db8>] vprintk_func+0x154/0x180
[    0.444522] [<ffffff8008104448>] printk+0x80/0xa0
[    0.444525] [<ffffff800832a944>] pstore_register+0x148/0x1f8
[    0.444529] [<ffffff800832cb5c>] ramoops_probe+0x56c/0x6e8
[    0.444537] [<ffffff8008551d64>] platform_drv_probe+0x58/0xa4
[    0.444544] [<ffffff800854f9c4>] driver_probe_device+0x204/0x438
[    0.444547] [<ffffff800854fe44>] __device_attach_driver+0xf8/0x110
[    0.444552] [<ffffff800854d6dc>] bus_for_each_drv+0x98/0xc8
[    0.444556] [<ffffff800854f6ec>] __device_attach+0xac/0x150
[    0.444559] [<ffffff800854fe80>] device_initial_probe+0x24/0x30
[    0.444563] [<ffffff800854e96c>] bus_probe_device+0x38/0x98
[    0.444567] [<ffffff800854c478>] device_add+0x318/0x560
[    0.444575] [<ffffff8008737440>] of_device_add+0x44/0x50
[    0.444579] [<ffffff80087379f8>] 
of_platform_device_create_pdata+0x8c/0xc4
[    0.444582] [<ffffff8008737a64>] of_platform_device_create+0x34/0x40
[    0.444593] [<ffffff8008e3e9e8>] 
of_platform_default_populate_init+0x58/0xa8
[    0.444596] [<ffffff8008083558>] do_one_initcall+0xa0/0x138
[    0.444605] [<ffffff8008e00f10>] kernel_init_freeable+0x198/0x24c
[    0.444610] [<ffffff8008925a7c>] kernel_init+0x18/0x108
[    0.444616] [<ffffff800808477c>] ret_from_fork+0x10/0x18
[    0.856135] console [pstore-1] enabled

Re: [PATCH 2/6] pstore: Add event tracing support

[Stephen Boyd]

Quoting Sai Prakash Ranjan (2018-09-11 03:46:01)
> On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
> > +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
> > +{
> > +     struct trace_iterator *iter;
> > +     struct trace_seq *s;
> > +     struct trace_event_call *event_call;
> > +     struct pstore_record record;
> > +     struct trace_event *event;
> > +     struct seq_buf *seq;
> > +     unsigned long flags;
> > +
> > +     if (!psinfo)
> > +             return;
> > +
> > +     if (unlikely(oops_in_progress))
> > +             return;
> > +
> > +     pstore_record_init(&record, psinfo);
> > +     record.type = PSTORE_TYPE_EVENT;
> > +
> > +     iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> > +     if (!iter)
> > +             return;
> > +
> > +     event_call = fbuffer->trace_file->event_call;
> > +     if (!event_call || !event_call->event.funcs ||
> > +         !event_call->event.funcs->trace)
> > +             goto fail_event;
> > +
> > +     event = &fbuffer->trace_file->event_call->event;
> > +
> > +     spin_lock_irqsave(&psinfo->buf_lock, flags);
> > +
> > +     trace_seq_init(&iter->seq);
> > +     iter->ent = fbuffer->entry;
> > +     event_call->event.funcs->trace(iter, 0, event);
> > +     trace_seq_putc(&iter->seq, 0);
> > +
> > +     if (seq->size > psinfo->bufsize)
> > +             seq->size = psinfo->bufsize;
> > +
> > +     s = &iter->seq;
> > +     seq = &s->seq;
> > +
> > +     record.buf = (char *)(seq->buffer);
> > +     record.size = seq->len;
> > +     psinfo->write(&record);
> > +
> > +     spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> > +
> > +fail_event:
> > +     kfree(iter);
> > +}
> > +
> > 
> 
> When tracing sched events on sdm845 mtp, I hit below bug repeatedly.
> Seems like pstore_event_call can be called in atomic context.
> I will respin the below fix in next version of the patch.
> Reviews on other parts would be appreciated, thanks.
> 
> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
> index d47dc93ac098..a497cf782ee8 100644
> --- a/fs/pstore/ftrace.c
> +++ b/fs/pstore/ftrace.c
> @@ -73,6 +73,7 @@ void notrace pstore_event_call(struct 
> trace_event_buffer *fbuffer)
>          struct trace_event *event;
>          struct seq_buf *seq;
>          unsigned long flags;
> +       gfp_t gfpflags;
> 
>          if (!psinfo)
>                  return;
> @@ -83,7 +84,9 @@ void notrace pstore_event_call(struct 
> trace_event_buffer *fbuffer)
>          pstore_record_init(&record, psinfo);
>          record.type = PSTORE_TYPE_EVENT;
> 
> -       iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> +       gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC : 
> GFP_KERNEL;
> +

Do you need to allocate at all? Can you throw the iter on the stack?

Using in_atomic() and irqs_disabled() to figure out if an atomic or a
non-atomic allocation should be used is not a good solution.

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/17/2018 11:08 PM, Stephen Boyd wrote:
> Quoting Sai Prakash Ranjan (2018-09-11 03:46:01)
>> On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
>>> +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
>>> +{
>>> +     struct trace_iterator *iter;
>>> +     struct trace_seq *s;
>>> +     struct trace_event_call *event_call;
>>> +     struct pstore_record record;
>>> +     struct trace_event *event;
>>> +     struct seq_buf *seq;
>>> +     unsigned long flags;
>>> +
>>> +     if (!psinfo)
>>> +             return;
>>> +
>>> +     if (unlikely(oops_in_progress))
>>> +             return;
>>> +
>>> +     pstore_record_init(&record, psinfo);
>>> +     record.type = PSTORE_TYPE_EVENT;
>>> +
>>> +     iter = kmalloc(sizeof(*iter), GFP_KERNEL);
>>> +     if (!iter)
>>> +             return;
>>> +
>>> +     event_call = fbuffer->trace_file->event_call;
>>> +     if (!event_call || !event_call->event.funcs ||
>>> +         !event_call->event.funcs->trace)
>>> +             goto fail_event;
>>> +
>>> +     event = &fbuffer->trace_file->event_call->event;
>>> +
>>> +     spin_lock_irqsave(&psinfo->buf_lock, flags);
>>> +
>>> +     trace_seq_init(&iter->seq);
>>> +     iter->ent = fbuffer->entry;
>>> +     event_call->event.funcs->trace(iter, 0, event);
>>> +     trace_seq_putc(&iter->seq, 0);
>>> +
>>> +     if (seq->size > psinfo->bufsize)
>>> +             seq->size = psinfo->bufsize;
>>> +
>>> +     s = &iter->seq;
>>> +     seq = &s->seq;
>>> +
>>> +     record.buf = (char *)(seq->buffer);
>>> +     record.size = seq->len;
>>> +     psinfo->write(&record);
>>> +
>>> +     spin_unlock_irqrestore(&psinfo->buf_lock, flags);
>>> +
>>> +fail_event:
>>> +     kfree(iter);
>>> +}
>>> +
>>>
>>
>> When tracing sched events on sdm845 mtp, I hit below bug repeatedly.
>> Seems like pstore_event_call can be called in atomic context.
>> I will respin the below fix in next version of the patch.
>> Reviews on other parts would be appreciated, thanks.
>>
>> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
>> index d47dc93ac098..a497cf782ee8 100644
>> --- a/fs/pstore/ftrace.c
>> +++ b/fs/pstore/ftrace.c
>> @@ -73,6 +73,7 @@ void notrace pstore_event_call(struct
>> trace_event_buffer *fbuffer)
>>           struct trace_event *event;
>>           struct seq_buf *seq;
>>           unsigned long flags;
>> +       gfp_t gfpflags;
>>
>>           if (!psinfo)
>>                   return;
>> @@ -83,7 +84,9 @@ void notrace pstore_event_call(struct
>> trace_event_buffer *fbuffer)
>>           pstore_record_init(&record, psinfo);
>>           record.type = PSTORE_TYPE_EVENT;
>>
>> -       iter = kmalloc(sizeof(*iter), GFP_KERNEL);
>> +       gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC :
>> GFP_KERNEL;
>> +
>

Hi Stephen

Thanks for the comments.

> Do you need to allocate at all? Can you throw the iter on the stack?
> 

Yes since we need to copy the contents to pstore buffer.

> Using in_atomic() and irqs_disabled() to figure out if an atomic or a
> non-atomic allocation should be used is not a good solution.
> 

I took reference from a similar use by graph_trace_open() which can be 
called in atomic context via ftrace_dump(). I am open to correct this if 
there is some other way.

Sai

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
> Currently pstore has function trace support which can be
> used to get the function call chain with limited data.
> Event tracing has extra data which is useful to debug wide
> variety of issues and is heavily used across the kernel.
> 
> Adding this support to pstore can be very helpful to debug
> different subsystems since almost all of them have trace
> events already available. And also it is useful to debug
> unknown resets or crashes since we can get lot more info
> from event tracing by viewing the last occurred events.
> 
> High frequency tracepoints such as sched and irq has also
> been tested. This implementation is similar to "tp_printk"
> command line feature of ftrace by Steven.
> 
> For example, sample pstore output of tracing sched events
> after reboot:
> 
>    # mount -t pstore pstore /sys/fs/pstore/
>    # tail /sys/fs/pstore/event-ramoops-0
>    sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=10 next_prio=120
>    sched_switch: prev_comm=rcu_preempt prev_pid=10 prev_prio=120 prev_state=R+ ==> next_comm=swapper/1 next_pid=0 next_prio=120
>    sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=002
>    sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=002
>    sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=11 next_prio=120
>    sched_switch: prev_comm=rcu_sched prev_pid=11 prev_prio=120 prev_state=R+ ==> next_comm=swapper/2 next_pid=0 next_prio=120
>    sched_waking: comm=reboot pid=1867 prio=120 target_cpu=000
>    sched_wakeup: comm=reboot pid=1867 prio=120 target_cpu=000
>    sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=reboot next_pid=1867 next_prio=120
> 
> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
> ---
>   fs/pstore/Kconfig          |  2 +-
>   fs/pstore/ftrace.c         | 55 ++++++++++++++++++++++++++++++++++++++
>   fs/pstore/inode.c          |  4 +++
>   fs/pstore/ram.c            | 44 +++++++++++++++++++++++++++---
>   include/linux/pstore.h     |  2 ++
>   include/linux/pstore_ram.h |  1 +
>   6 files changed, 104 insertions(+), 4 deletions(-)
> 
> diff --git a/fs/pstore/Kconfig b/fs/pstore/Kconfig
> index 503086f7f7c1..6fe087b13a51 100644
> --- a/fs/pstore/Kconfig
> +++ b/fs/pstore/Kconfig
> @@ -126,7 +126,7 @@ config PSTORE_PMSG
>   
>   config PSTORE_FTRACE
>   	bool "Persistent function tracer"
> -	depends on PSTORE
> +	depends on PSTORE && PSTORE!=m
>   	depends on FUNCTION_TRACER
>   	depends on DEBUG_FS
>   	help
> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
> index 06aab07b6bb7..d47dc93ac098 100644
> --- a/fs/pstore/ftrace.c
> +++ b/fs/pstore/ftrace.c
> @@ -24,6 +24,8 @@
>   #include <linux/debugfs.h>
>   #include <linux/err.h>
>   #include <linux/cache.h>
> +#include <linux/slab.h>
> +#include <linux/trace_events.h>
>   #include <asm/barrier.h>
>   #include "internal.h"
>   
> @@ -62,6 +64,59 @@ static struct ftrace_ops pstore_ftrace_ops __read_mostly = {
>   	.func	= pstore_ftrace_call,
>   };
>   
> +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
> +{
> +	struct trace_iterator *iter;
> +	struct trace_seq *s;
> +	struct trace_event_call *event_call;
> +	struct pstore_record record;
> +	struct trace_event *event;
> +	struct seq_buf *seq;
> +	unsigned long flags;
> +
> +	if (!psinfo)
> +		return;
> +
> +	if (unlikely(oops_in_progress))
> +		return;
> +
> +	pstore_record_init(&record, psinfo);
> +	record.type = PSTORE_TYPE_EVENT;
> +
> +	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> +	if (!iter)
> +		return;
> +
> +	event_call = fbuffer->trace_file->event_call;
> +	if (!event_call || !event_call->event.funcs ||
> +	    !event_call->event.funcs->trace)
> +		goto fail_event;
> +
> +	event = &fbuffer->trace_file->event_call->event;
> +
> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
> +
> +	trace_seq_init(&iter->seq);
> +	iter->ent = fbuffer->entry;
> +	event_call->event.funcs->trace(iter, 0, event);
> +	trace_seq_putc(&iter->seq, 0);
> +
> +	if (seq->size > psinfo->bufsize)
> +		seq->size = psinfo->bufsize;
> +
> +	s = &iter->seq;
> +	seq = &s->seq;
> +
> +	record.buf = (char *)(seq->buffer);
> +	record.size = seq->len;
> +	psinfo->write(&record);
> +
> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> +
> +fail_event:
> +	kfree(iter);
> +}
> +
>   static DEFINE_MUTEX(pstore_ftrace_lock);
>   static bool pstore_ftrace_enabled;
>   
> diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
> index 5fcb845b9fec..f099152abbbd 100644
> --- a/fs/pstore/inode.c
> +++ b/fs/pstore/inode.c
> @@ -345,6 +345,10 @@ int pstore_mkfile(struct dentry *root, struct pstore_record *record)
>   		scnprintf(name, sizeof(name), "console-%s-%llu",
>   			  record->psi->name, record->id);
>   		break;
> +	case PSTORE_TYPE_EVENT:
> +		scnprintf(name, sizeof(name), "event-%s-%llu",
> +			  record->psi->name, record->id);
> +		break;
>   	case PSTORE_TYPE_FTRACE:
>   		scnprintf(name, sizeof(name), "ftrace-%s-%llu",
>   			  record->psi->name, record->id);
> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
> index bbd1e357c23d..f60d41c0309e 100644
> --- a/fs/pstore/ram.c
> +++ b/fs/pstore/ram.c
> @@ -48,6 +48,10 @@ static ulong ramoops_console_size = MIN_MEM_SIZE;
>   module_param_named(console_size, ramoops_console_size, ulong, 0400);
>   MODULE_PARM_DESC(console_size, "size of kernel console log");
>   
> +static ulong ramoops_event_size = MIN_MEM_SIZE;
> +module_param_named(event_size, ramoops_event_size, ulong, 0400);
> +MODULE_PARM_DESC(event_size, "size of event log");
> +
>   static ulong ramoops_ftrace_size = MIN_MEM_SIZE;
>   module_param_named(ftrace_size, ramoops_ftrace_size, ulong, 0400);
>   MODULE_PARM_DESC(ftrace_size, "size of ftrace log");
> @@ -86,6 +90,7 @@ MODULE_PARM_DESC(ramoops_ecc,
>   struct ramoops_context {
>   	struct persistent_ram_zone **dprzs;	/* Oops dump zones */
>   	struct persistent_ram_zone *cprz;	/* Console zone */
> +	struct persistent_ram_zone *eprz;       /* Event zone */
>   	struct persistent_ram_zone **fprzs;	/* Ftrace zones */
>   	struct persistent_ram_zone *mprz;	/* PMSG zone */
>   	phys_addr_t phys_addr;
> @@ -93,6 +98,7 @@ struct ramoops_context {
>   	unsigned int memtype;
>   	size_t record_size;
>   	size_t console_size;
> +	size_t event_size;
>   	size_t ftrace_size;
>   	size_t pmsg_size;
>   	int dump_oops;
> @@ -103,6 +109,7 @@ struct ramoops_context {
>   	/* _read_cnt need clear on ramoops_pstore_open */
>   	unsigned int dump_read_cnt;
>   	unsigned int console_read_cnt;
> +	unsigned int event_read_cnt;
>   	unsigned int max_ftrace_cnt;
>   	unsigned int ftrace_read_cnt;
>   	unsigned int pmsg_read_cnt;
> @@ -118,6 +125,7 @@ static int ramoops_pstore_open(struct pstore_info *psi)
>   
>   	cxt->dump_read_cnt = 0;
>   	cxt->console_read_cnt = 0;
> +	cxt->event_read_cnt = 0;
>   	cxt->ftrace_read_cnt = 0;
>   	cxt->pmsg_read_cnt = 0;
>   	return 0;
> @@ -277,6 +285,11 @@ static ssize_t ramoops_pstore_read(struct pstore_record *record)
>   					   1, &record->id, &record->type,
>   					   PSTORE_TYPE_CONSOLE, 0);
>   
> +	if (!prz_ok(prz))
> +		prz = ramoops_get_next_prz(&cxt->eprz, &cxt->event_read_cnt,
> +					   1, &record->id, &record->type,
> +					   PSTORE_TYPE_EVENT, 0);
> +
>   	if (!prz_ok(prz))
>   		prz = ramoops_get_next_prz(&cxt->mprz, &cxt->pmsg_read_cnt,
>   					   1, &record->id, &record->type,
> @@ -385,6 +398,11 @@ static int notrace ramoops_pstore_write(struct pstore_record *record)
>   			return -ENOMEM;
>   		persistent_ram_write(cxt->cprz, record->buf, record->size);
>   		return 0;
> +	} else if (record->type == PSTORE_TYPE_EVENT) {
> +		if (!cxt->eprz)
> +			return -ENOMEM;
> +		persistent_ram_write(cxt->eprz, record->buf, record->size);
> +		return 0;
>   	} else if (record->type == PSTORE_TYPE_FTRACE) {
>   		int zonenum;
>   
> @@ -475,6 +493,9 @@ static int ramoops_pstore_erase(struct pstore_record *record)
>   	case PSTORE_TYPE_CONSOLE:
>   		prz = cxt->cprz;
>   		break;
> +	case PSTORE_TYPE_EVENT:
> +		prz = cxt->eprz;
> +		break;
>   	case PSTORE_TYPE_FTRACE:
>   		if (record->id >= cxt->max_ftrace_cnt)
>   			return -EINVAL;
> @@ -699,6 +720,7 @@ static int ramoops_parse_dt(struct platform_device *pdev,
>   
>   	parse_size("record-size", pdata->record_size);
>   	parse_size("console-size", pdata->console_size);
> +	parse_size("event-size", pdata->event_size);
>   	parse_size("ftrace-size", pdata->ftrace_size);
>   	parse_size("pmsg-size", pdata->pmsg_size);
>   	parse_size("ecc-size", pdata->ecc_info.ecc_size);
> @@ -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->event_size && !pdata->ftrace_size &&
> +			!pdata->pmsg_size)) {
>   		pr_err("The memory size and the record/console size must be "
>   			"non-zero\n");
>   		goto fail_out;
> @@ -757,6 +780,8 @@ static int ramoops_probe(struct platform_device *pdev)
>   		pdata->record_size = rounddown_pow_of_two(pdata->record_size);
>   	if (pdata->console_size && !is_power_of_2(pdata->console_size))
>   		pdata->console_size = rounddown_pow_of_two(pdata->console_size);
> +	if (pdata->event_size && !is_power_of_2(pdata->event_size))
> +		pdata->event_size = rounddown_pow_of_two(pdata->event_size);
>   	if (pdata->ftrace_size && !is_power_of_2(pdata->ftrace_size))
>   		pdata->ftrace_size = rounddown_pow_of_two(pdata->ftrace_size);
>   	if (pdata->pmsg_size && !is_power_of_2(pdata->pmsg_size))
> @@ -767,6 +792,7 @@ static int ramoops_probe(struct platform_device *pdev)
>   	cxt->memtype = pdata->mem_type;
>   	cxt->record_size = pdata->record_size;
>   	cxt->console_size = pdata->console_size;
> +	cxt->event_size = pdata->event_size;
>   	cxt->ftrace_size = pdata->ftrace_size;
>   	cxt->pmsg_size = pdata->pmsg_size;
>   	cxt->dump_oops = pdata->dump_oops;
> @@ -775,8 +801,8 @@ 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;
> +	dump_mem_sz = cxt->size - cxt->console_size - cxt->event_size
> +			- cxt->ftrace_size - cxt->pmsg_size;
>   	err = ramoops_init_przs("dump", dev, cxt, &cxt->dprzs, &paddr,
>   				dump_mem_sz, cxt->record_size,
>   				&cxt->max_dump_cnt, 0, 0);
> @@ -788,6 +814,11 @@ static int ramoops_probe(struct platform_device *pdev)
>   	if (err)
>   		goto fail_init_cprz;
>   
> +	err = ramoops_init_prz("event", dev, cxt, &cxt->eprz, &paddr,
> +			       cxt->event_size, 0);
> +	if (err)
> +		goto fail_init_eprz;
> +
>   	cxt->max_ftrace_cnt = (cxt->flags & RAMOOPS_FLAG_FTRACE_PER_CPU)
>   				? nr_cpu_ids
>   				: 1;
> @@ -825,6 +856,8 @@ static int ramoops_probe(struct platform_device *pdev)
>   	cxt->pstore.flags = PSTORE_FLAGS_DMESG;
>   	if (cxt->console_size)
>   		cxt->pstore.flags |= PSTORE_FLAGS_CONSOLE;
> +	if (cxt->event_size)
> +		cxt->pstore.flags |= PSTORE_FLAGS_EVENT;
>   	if (cxt->ftrace_size)
>   		cxt->pstore.flags |= PSTORE_FLAGS_FTRACE;
>   	if (cxt->pmsg_size)
> @@ -845,6 +878,7 @@ static int ramoops_probe(struct platform_device *pdev)
>   	record_size = pdata->record_size;
>   	dump_oops = pdata->dump_oops;
>   	ramoops_console_size = pdata->console_size;
> +	ramoops_event_size = pdata->event_size;
>   	ramoops_pmsg_size = pdata->pmsg_size;
>   	ramoops_ftrace_size = pdata->ftrace_size;
>   
> @@ -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->eprz);
> +fail_init_eprz:
>   	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->eprz);
>   	persistent_ram_free(cxt->mprz);
>   	persistent_ram_free(cxt->cprz);
>   	ramoops_free_przs(cxt);
> @@ -916,6 +953,7 @@ static void ramoops_register_dummy(void)
>   	dummy_data->mem_type = mem_type;
>   	dummy_data->record_size = record_size;
>   	dummy_data->console_size = ramoops_console_size;
> +	dummy_data->event_size = ramoops_event_size;
>   	dummy_data->ftrace_size = ramoops_ftrace_size;
>   	dummy_data->pmsg_size = ramoops_pmsg_size;
>   	dummy_data->dump_oops = dump_oops;
> diff --git a/include/linux/pstore.h b/include/linux/pstore.h
> index a15bc4d48752..c31bb9567b4a 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_EVENT	= 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_EVENT	(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..f01055c6cc40 100644
> --- a/include/linux/pstore_ram.h
> +++ b/include/linux/pstore_ram.h
> @@ -95,6 +95,7 @@ struct ramoops_platform_data {
>   	unsigned int	mem_type;
>   	unsigned long	record_size;
>   	unsigned long	console_size;
> +	unsigned long	event_size;
>   	unsigned long	ftrace_size;
>   	unsigned long	pmsg_size;
>   	int		dump_oops;
> 

Hi,

Anyone here?

Re: [PATCH 2/6] pstore: Add event tracing support

[Kees Cook]

On Sun, Sep 16, 2018 at 6:55 AM, Joel Fernandes <joel@joelfernandes.org> wrote:
> On Sun, Sep 16, 2018, 12:08 AM Sai Prakash Ranjan
> <saiprakash.ranjan@codeaurora.org> wrote:
>>
>> On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
>> > Currently pstore has function trace support which can be
>> > used to get the function call chain with limited data.
>> > Event tracing has extra data which is useful to debug wide
>> > variety of issues and is heavily used across the kernel.
>> >
>> > Adding this support to pstore can be very helpful to debug
>> > different subsystems since almost all of them have trace
>> > events already available. And also it is useful to debug
>> > unknown resets or crashes since we can get lot more info
>> > from event tracing by viewing the last occurred events.
>>
>> Anyone here?
>
> Sorry for the top post. I've been wanting to do this as well for some time.
> It's quite useful. I am out of office this week and away from work machine.
> I will take a look at your patches next week once I'm back at work. Thanks.

If Steven agrees this shouldn't live in ftrace directly and Joel
reviews these patches, I think it should be fine. I'm travelling, but
I can review it hopefully later this week.

-Kees

-- 
Kees Cook
Pixel Security

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/17/2018 8:24 PM, Kees Cook wrote:
> On Sun, Sep 16, 2018 at 6:55 AM, Joel Fernandes <joel@joelfernandes.org> wrote:
>> On Sun, Sep 16, 2018, 12:08 AM Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>> On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote:
>>>> Currently pstore has function trace support which can be
>>>> used to get the function call chain with limited data.
>>>> Event tracing has extra data which is useful to debug wide
>>>> variety of issues and is heavily used across the kernel.
>>>>
>>>> Adding this support to pstore can be very helpful to debug
>>>> different subsystems since almost all of them have trace
>>>> events already available. And also it is useful to debug
>>>> unknown resets or crashes since we can get lot more info
>>>> from event tracing by viewing the last occurred events.
>>>
>>> Anyone here?
>>
>> Sorry for the top post. I've been wanting to do this as well for some time.
>> It's quite useful. I am out of office this week and away from work machine.
>> I will take a look at your patches next week once I'm back at work. Thanks.
> 
> If Steven agrees this shouldn't live in ftrace directly and Joel
> reviews these patches, I think it should be fine. I'm travelling, but
> I can review it hopefully later this week.
> 

Thank you Kees.

- Sai

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/16/2018 7:25 PM, Joel Fernandes wrote:
> Sorry for the top post. I've been wanting to do this as well for some 
> time. It's quite useful. I am out of office this week and away from work 
> machine. I will take a look at your patches next week once I'm back at 
> work. Thanks.
> 
> Best,
> J
> 

Cool, thanks Joel.

Re: [PATCH 2/6] pstore: Add event tracing support

[Steven Rostedt]

On Sun, 16 Sep 2018 12:37:52 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> Hi,
> 
> Anyone here?

You also just caught me from coming back from a trip. I'm looking at
your patches now.

-- Steve

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/18/2018 4:34 AM, Steven Rostedt wrote:
> On Sun, 16 Sep 2018 12:37:52 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
>> Hi,
>>
>> Anyone here?
> 
> You also just caught me from coming back from a trip. I'm looking at
> your patches now.
> 
> -- Steve
> 

Thanks Steve, I just thought you guys might have missed the patch.

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Steven Rostedt]

On Sun,  9 Sep 2018 01:57:03 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:


> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
> ---
>  fs/pstore/Kconfig          |  2 +-
>  fs/pstore/ftrace.c         | 55 ++++++++++++++++++++++++++++++++++++++
>  fs/pstore/inode.c          |  4 +++
>  fs/pstore/ram.c            | 44 +++++++++++++++++++++++++++---
>  include/linux/pstore.h     |  2 ++
>  include/linux/pstore_ram.h |  1 +
>  6 files changed, 104 insertions(+), 4 deletions(-)
> 
> diff --git a/fs/pstore/Kconfig b/fs/pstore/Kconfig
> index 503086f7f7c1..6fe087b13a51 100644
> --- a/fs/pstore/Kconfig
> +++ b/fs/pstore/Kconfig
> @@ -126,7 +126,7 @@ config PSTORE_PMSG
>  
>  config PSTORE_FTRACE
>  	bool "Persistent function tracer"
> -	depends on PSTORE
> +	depends on PSTORE && PSTORE!=m
>  	depends on FUNCTION_TRACER
>  	depends on DEBUG_FS
>  	help
> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
> index 06aab07b6bb7..d47dc93ac098 100644
> --- a/fs/pstore/ftrace.c
> +++ b/fs/pstore/ftrace.c
> @@ -24,6 +24,8 @@
>  #include <linux/debugfs.h>
>  #include <linux/err.h>
>  #include <linux/cache.h>
> +#include <linux/slab.h>
> +#include <linux/trace_events.h>
>  #include <asm/barrier.h>
>  #include "internal.h"
>  
> @@ -62,6 +64,59 @@ static struct ftrace_ops pstore_ftrace_ops __read_mostly = {
>  	.func	= pstore_ftrace_call,
>  };
>  
> +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
> +{
> +	struct trace_iterator *iter;
> +	struct trace_seq *s;
> +	struct trace_event_call *event_call;
> +	struct pstore_record record;
> +	struct trace_event *event;
> +	struct seq_buf *seq;
> +	unsigned long flags;
> +
> +	if (!psinfo)
> +		return;
> +
> +	if (unlikely(oops_in_progress))
> +		return;
> +
> +	pstore_record_init(&record, psinfo);
> +	record.type = PSTORE_TYPE_EVENT;
> +
> +	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> +	if (!iter)
> +		return;

It looks like pstore_event_call() gets called from a trace event. You
can't call kmalloc() from one. One thing is that kmalloc has
tracepoints itself. You trace those you just entered an infinite loop.


> +
> +	event_call = fbuffer->trace_file->event_call;
> +	if (!event_call || !event_call->event.funcs ||
> +	    !event_call->event.funcs->trace)
> +		goto fail_event;
> +
> +	event = &fbuffer->trace_file->event_call->event;
> +
> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
> +
> +	trace_seq_init(&iter->seq);
> +	iter->ent = fbuffer->entry;

I guess what you are doing is needing to translate the raw data into
ascii output, and need the trace_iterator to do so.

You are already under a psinfo->buf_lock. Add a dummy iterator to that
and use it instead.

	trace_seq_init(&psinfo->iter->seq);

> +	event_call->event.funcs->trace(iter, 0, event);

				      (psinfo->iter, 0 , event);

etc.

> +	trace_seq_putc(&iter->seq, 0);
> +
> +	if (seq->size > psinfo->bufsize)
> +		seq->size = psinfo->bufsize;
> +
> +	s = &iter->seq;
> +	seq = &s->seq;
> +
> +	record.buf = (char *)(seq->buffer);
> +	record.size = seq->len;
> +	psinfo->write(&record);
> +
> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);

You may also need to convert these spin_locks into raw_spin_locks as
when PREEMPT_RT enters the kernel you don't want them to turn into
mutexes. 

But that can be another patch.

-- Steve

> +
> +fail_event:
> +	kfree(iter);
> +}
> +
>  static DEFINE_MUTEX(pstore_ftrace_lock);
>  static bool pstore_ftrace_enabled;
>  
> diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
> index 5fcb845b9fec..f099152abbbd 100644
> --- a/fs/pstore/inode.c
> +++ b/fs/pstore/inode.c
> @@ -345,6 +345,10 @@ int pstore_mkfile(struct dentry *root, struct pstore_record *record)
>  		scnprintf(name, sizeof(name), "console-%s-%llu",
>  			  record->psi->name, record->id);
>  		break;
> +	case PSTORE_TYPE_EVENT:
> +		scnprintf(name, sizeof(name), "event-%s-%llu",
> +			  record->psi->name, record->id);
> +		break;
>  	case PSTORE_TYPE_FTRACE:
>  		scnprintf(name, sizeof(name), "ftrace-%s-%llu",
>  			  record->psi->name, record->id);
> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
> index bbd1e357c23d..f60d41c0309e 100644
> --- a/fs/pstore/ram.c
> +++ b/fs/pstore/ram.c
> @@ -48,6 +48,10 @@ static ulong ramoops_console_size = MIN_MEM_SIZE;
>  module_param_named(console_size, ramoops_console_size, ulong, 0400);
>  MODULE_PARM_DESC(console_size, "size of kernel console log");
>  
> +static ulong ramoops_event_size = MIN_MEM_SIZE;
> +module_param_named(event_size, ramoops_event_size, ulong, 0400);
> +MODULE_PARM_DESC(event_size, "size of event log");
> +
>  static ulong ramoops_ftrace_size = MIN_MEM_SIZE;
>  module_param_named(ftrace_size, ramoops_ftrace_size, ulong, 0400);
>  MODULE_PARM_DESC(ftrace_size, "size of ftrace log");
> @@ -86,6 +90,7 @@ MODULE_PARM_DESC(ramoops_ecc,
>  struct ramoops_context {
>  	struct persistent_ram_zone **dprzs;	/* Oops dump zones */
>  	struct persistent_ram_zone *cprz;	/* Console zone */
> +	struct persistent_ram_zone *eprz;       /* Event zone */
>  	struct persistent_ram_zone **fprzs;	/* Ftrace zones */
>  	struct persistent_ram_zone *mprz;	/* PMSG zone */
>  	phys_addr_t phys_addr;
> @@ -93,6 +98,7 @@ struct ramoops_context {
>  	unsigned int memtype;
>  	size_t record_size;
>  	size_t console_size;
> +	size_t event_size;
>  	size_t ftrace_size;
>  	size_t pmsg_size;
>  	int dump_oops;
> @@ -103,6 +109,7 @@ struct ramoops_context {
>  	/* _read_cnt need clear on ramoops_pstore_open */
>  	unsigned int dump_read_cnt;
>  	unsigned int console_read_cnt;
> +	unsigned int event_read_cnt;
>  	unsigned int max_ftrace_cnt;
>  	unsigned int ftrace_read_cnt;
>  	unsigned int pmsg_read_cnt;
> @@ -118,6 +125,7 @@ static int ramoops_pstore_open(struct pstore_info *psi)
>  
>  	cxt->dump_read_cnt = 0;
>  	cxt->console_read_cnt = 0;
> +	cxt->event_read_cnt = 0;
>  	cxt->ftrace_read_cnt = 0;
>  	cxt->pmsg_read_cnt = 0;
>  	return 0;
> @@ -277,6 +285,11 @@ static ssize_t ramoops_pstore_read(struct pstore_record *record)
>  					   1, &record->id, &record->type,
>  					   PSTORE_TYPE_CONSOLE, 0);
>  
> +	if (!prz_ok(prz))
> +		prz = ramoops_get_next_prz(&cxt->eprz, &cxt->event_read_cnt,
> +					   1, &record->id, &record->type,
> +					   PSTORE_TYPE_EVENT, 0);
> +
>  	if (!prz_ok(prz))
>  		prz = ramoops_get_next_prz(&cxt->mprz, &cxt->pmsg_read_cnt,
>  					   1, &record->id, &record->type,
> @@ -385,6 +398,11 @@ static int notrace ramoops_pstore_write(struct pstore_record *record)
>  			return -ENOMEM;
>  		persistent_ram_write(cxt->cprz, record->buf, record->size);
>  		return 0;
> +	} else if (record->type == PSTORE_TYPE_EVENT) {
> +		if (!cxt->eprz)
> +			return -ENOMEM;
> +		persistent_ram_write(cxt->eprz, record->buf, record->size);
> +		return 0;
>  	} else if (record->type == PSTORE_TYPE_FTRACE) {
>  		int zonenum;
>  
> @@ -475,6 +493,9 @@ static int ramoops_pstore_erase(struct pstore_record *record)
>  	case PSTORE_TYPE_CONSOLE:
>  		prz = cxt->cprz;
>  		break;
> +	case PSTORE_TYPE_EVENT:
> +		prz = cxt->eprz;
> +		break;
>  	case PSTORE_TYPE_FTRACE:
>  		if (record->id >= cxt->max_ftrace_cnt)
>  			return -EINVAL;
> @@ -699,6 +720,7 @@ static int ramoops_parse_dt(struct platform_device *pdev,
>  
>  	parse_size("record-size", pdata->record_size);
>  	parse_size("console-size", pdata->console_size);
> +	parse_size("event-size", pdata->event_size);
>  	parse_size("ftrace-size", pdata->ftrace_size);
>  	parse_size("pmsg-size", pdata->pmsg_size);
>  	parse_size("ecc-size", pdata->ecc_info.ecc_size);
> @@ -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->event_size && !pdata->ftrace_size &&
> +			!pdata->pmsg_size)) {
>  		pr_err("The memory size and the record/console size must be "
>  			"non-zero\n");
>  		goto fail_out;
> @@ -757,6 +780,8 @@ static int ramoops_probe(struct platform_device *pdev)
>  		pdata->record_size = rounddown_pow_of_two(pdata->record_size);
>  	if (pdata->console_size && !is_power_of_2(pdata->console_size))
>  		pdata->console_size = rounddown_pow_of_two(pdata->console_size);
> +	if (pdata->event_size && !is_power_of_2(pdata->event_size))
> +		pdata->event_size = rounddown_pow_of_two(pdata->event_size);
>  	if (pdata->ftrace_size && !is_power_of_2(pdata->ftrace_size))
>  		pdata->ftrace_size = rounddown_pow_of_two(pdata->ftrace_size);
>  	if (pdata->pmsg_size && !is_power_of_2(pdata->pmsg_size))
> @@ -767,6 +792,7 @@ static int ramoops_probe(struct platform_device *pdev)
>  	cxt->memtype = pdata->mem_type;
>  	cxt->record_size = pdata->record_size;
>  	cxt->console_size = pdata->console_size;
> +	cxt->event_size = pdata->event_size;
>  	cxt->ftrace_size = pdata->ftrace_size;
>  	cxt->pmsg_size = pdata->pmsg_size;
>  	cxt->dump_oops = pdata->dump_oops;
> @@ -775,8 +801,8 @@ 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;
> +	dump_mem_sz = cxt->size - cxt->console_size - cxt->event_size
> +			- cxt->ftrace_size - cxt->pmsg_size;
>  	err = ramoops_init_przs("dump", dev, cxt, &cxt->dprzs, &paddr,
>  				dump_mem_sz, cxt->record_size,
>  				&cxt->max_dump_cnt, 0, 0);
> @@ -788,6 +814,11 @@ static int ramoops_probe(struct platform_device *pdev)
>  	if (err)
>  		goto fail_init_cprz;
>  
> +	err = ramoops_init_prz("event", dev, cxt, &cxt->eprz, &paddr,
> +			       cxt->event_size, 0);
> +	if (err)
> +		goto fail_init_eprz;
> +
>  	cxt->max_ftrace_cnt = (cxt->flags & RAMOOPS_FLAG_FTRACE_PER_CPU)
>  				? nr_cpu_ids
>  				: 1;
> @@ -825,6 +856,8 @@ static int ramoops_probe(struct platform_device *pdev)
>  	cxt->pstore.flags = PSTORE_FLAGS_DMESG;
>  	if (cxt->console_size)
>  		cxt->pstore.flags |= PSTORE_FLAGS_CONSOLE;
> +	if (cxt->event_size)
> +		cxt->pstore.flags |= PSTORE_FLAGS_EVENT;
>  	if (cxt->ftrace_size)
>  		cxt->pstore.flags |= PSTORE_FLAGS_FTRACE;
>  	if (cxt->pmsg_size)
> @@ -845,6 +878,7 @@ static int ramoops_probe(struct platform_device *pdev)
>  	record_size = pdata->record_size;
>  	dump_oops = pdata->dump_oops;
>  	ramoops_console_size = pdata->console_size;
> +	ramoops_event_size = pdata->event_size;
>  	ramoops_pmsg_size = pdata->pmsg_size;
>  	ramoops_ftrace_size = pdata->ftrace_size;
>  
> @@ -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->eprz);
> +fail_init_eprz:
>  	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->eprz);
>  	persistent_ram_free(cxt->mprz);
>  	persistent_ram_free(cxt->cprz);
>  	ramoops_free_przs(cxt);
> @@ -916,6 +953,7 @@ static void ramoops_register_dummy(void)
>  	dummy_data->mem_type = mem_type;
>  	dummy_data->record_size = record_size;
>  	dummy_data->console_size = ramoops_console_size;
> +	dummy_data->event_size = ramoops_event_size;
>  	dummy_data->ftrace_size = ramoops_ftrace_size;
>  	dummy_data->pmsg_size = ramoops_pmsg_size;
>  	dummy_data->dump_oops = dump_oops;
> diff --git a/include/linux/pstore.h b/include/linux/pstore.h
> index a15bc4d48752..c31bb9567b4a 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_EVENT	= 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_EVENT	(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..f01055c6cc40 100644
> --- a/include/linux/pstore_ram.h
> +++ b/include/linux/pstore_ram.h
> @@ -95,6 +95,7 @@ struct ramoops_platform_data {
>  	unsigned int	mem_type;
>  	unsigned long	record_size;
>  	unsigned long	console_size;
> +	unsigned long	event_size;
>  	unsigned long	ftrace_size;
>  	unsigned long	pmsg_size;
>  	int		dump_oops;

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/18/2018 5:04 AM, Steven Rostedt wrote:
> 
> It looks like pstore_event_call() gets called from a trace event. You
> can't call kmalloc() from one. One thing is that kmalloc has
> tracepoints itself. You trace those you just entered an infinite loop.
> 
> 

Ok will remove it in v2. But any alternative way to do this?

>> +
>> +	event_call = fbuffer->trace_file->event_call;
>> +	if (!event_call || !event_call->event.funcs ||
>> +	    !event_call->event.funcs->trace)
>> +		goto fail_event;
>> +
>> +	event = &fbuffer->trace_file->event_call->event;
>> +
>> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
>> +
>> +	trace_seq_init(&iter->seq);
>> +	iter->ent = fbuffer->entry;
> 
> I guess what you are doing is needing to translate the raw data into
> ascii output, and need the trace_iterator to do so.
> 
> You are already under a psinfo->buf_lock. Add a dummy iterator to that
> and use it instead.
> 
> 	trace_seq_init(&psinfo->iter->seq);
> 
>> +	event_call->event.funcs->trace(iter, 0, event);
> 
> 				      (psinfo->iter, 0 , event);
> 
> etc.
> 

Sure, will update in v2.

>> +	trace_seq_putc(&iter->seq, 0);
>> +
>> +	if (seq->size > psinfo->bufsize)
>> +		seq->size = psinfo->bufsize;
>> +
>> +	s = &iter->seq;
>> +	seq = &s->seq;
>> +
>> +	record.buf = (char *)(seq->buffer);
>> +	record.size = seq->len;
>> +	psinfo->write(&record);
>> +
>> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> 
> You may also need to convert these spin_locks into raw_spin_locks as
> when PREEMPT_RT enters the kernel you don't want them to turn into
> mutexes.
> 
> But that can be another patch.
> 

I will change this in v2, but can't we have it in same patch?

Thanks,
Sai

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Steven Rostedt]

On Tue, 18 Sep 2018 23:22:48 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> On 9/18/2018 5:04 AM, Steven Rostedt wrote:
> > 
> > It looks like pstore_event_call() gets called from a trace event. You
> > can't call kmalloc() from one. One thing is that kmalloc has
> > tracepoints itself. You trace those you just entered an infinite loop.
> > 
> >   
> 
> Ok will remove it in v2. But any alternative way to do this?

I think I describe it below.

> 
> >> +
> >> +	event_call = fbuffer->trace_file->event_call;
> >> +	if (!event_call || !event_call->event.funcs ||
> >> +	    !event_call->event.funcs->trace)
> >> +		goto fail_event;
> >> +
> >> +	event = &fbuffer->trace_file->event_call->event;
> >> +
> >> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
> >> +
> >> +	trace_seq_init(&iter->seq);
> >> +	iter->ent = fbuffer->entry;  
> > 
> > I guess what you are doing is needing to translate the raw data into
> > ascii output, and need the trace_iterator to do so.
> > 
> > You are already under a psinfo->buf_lock. Add a dummy iterator to that
> > and use it instead.
> > 
> > 	trace_seq_init(&psinfo->iter->seq);
> >   
> >> +	event_call->event.funcs->trace(iter, 0, event);  
> > 
> > 				      (psinfo->iter, 0 , event);
> > 
> > etc.
> >   
> 
> Sure, will update in v2.
> 
> >> +	trace_seq_putc(&iter->seq, 0);
> >> +
> >> +	if (seq->size > psinfo->bufsize)
> >> +		seq->size = psinfo->bufsize;
> >> +
> >> +	s = &iter->seq;
> >> +	seq = &s->seq;
> >> +
> >> +	record.buf = (char *)(seq->buffer);
> >> +	record.size = seq->len;
> >> +	psinfo->write(&record);
> >> +
> >> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);  
> > 
> > You may also need to convert these spin_locks into raw_spin_locks as
> > when PREEMPT_RT enters the kernel you don't want them to turn into
> > mutexes.
> > 
> > But that can be another patch.
> >   
> 
> I will change this in v2, but can't we have it in same patch?

I suggested a separate patch because buf_lock is used elsewhere.
Changing it to "raw_spin_lock" will affect more than just what this
patch series does. Thus, I recommend making it a separate patch to keep
this patch series from being more intrusive than it needs to be.

Thanks!

-- Steve

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/19/2018 2:14 AM, Steven Rostedt wrote:
> On Tue, 18 Sep 2018 23:22:48 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
>> On 9/18/2018 5:04 AM, Steven Rostedt wrote:
>>>
>>> It looks like pstore_event_call() gets called from a trace event. You
>>> can't call kmalloc() from one. One thing is that kmalloc has
>>> tracepoints itself. You trace those you just entered an infinite loop.
>>>
>>>    
>>
>> Ok will remove it in v2. But any alternative way to do this?
> 
> I think I describe it below.
> 

Ok got it, will change and post the 2nd version soon.

>>
>>>> +
>>>> +	event_call = fbuffer->trace_file->event_call;
>>>> +	if (!event_call || !event_call->event.funcs ||
>>>> +	    !event_call->event.funcs->trace)
>>>> +		goto fail_event;
>>>> +
>>>> +	event = &fbuffer->trace_file->event_call->event;
>>>> +
>>>> +	spin_lock_irqsave(&psinfo->buf_lock, flags);
>>>> +
>>>> +	trace_seq_init(&iter->seq);
>>>> +	iter->ent = fbuffer->entry;
>>>
>>> I guess what you are doing is needing to translate the raw data into
>>> ascii output, and need the trace_iterator to do so.
>>>
>>> You are already under a psinfo->buf_lock. Add a dummy iterator to that
>>> and use it instead.
>>>
>>> 	trace_seq_init(&psinfo->iter->seq);
>>>    
>>>> +	event_call->event.funcs->trace(iter, 0, event);
>>>
>>> 				      (psinfo->iter, 0 , event);
>>>
>>> etc.
>>>    
>>
>> Sure, will update in v2.
>>
>>>> +	trace_seq_putc(&iter->seq, 0);
>>>> +
>>>> +	if (seq->size > psinfo->bufsize)
>>>> +		seq->size = psinfo->bufsize;
>>>> +
>>>> +	s = &iter->seq;
>>>> +	seq = &s->seq;
>>>> +
>>>> +	record.buf = (char *)(seq->buffer);
>>>> +	record.size = seq->len;
>>>> +	psinfo->write(&record);
>>>> +
>>>> +	spin_unlock_irqrestore(&psinfo->buf_lock, flags);
>>>
>>> You may also need to convert these spin_locks into raw_spin_locks as
>>> when PREEMPT_RT enters the kernel you don't want them to turn into
>>> mutexes.
>>>
>>> But that can be another patch.
>>>    
>>
>> I will change this in v2, but can't we have it in same patch?
> 
> I suggested a separate patch because buf_lock is used elsewhere.
> Changing it to "raw_spin_lock" will affect more than just what this
> patch series does. Thus, I recommend making it a separate patch to keep
> this patch series from being more intrusive than it needs to be.
> 

Sure, thanks a lot.

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/19/2018 2:43 AM, Sai Prakash Ranjan wrote:
> On 9/19/2018 2:14 AM, Steven Rostedt wrote:
>> On Tue, 18 Sep 2018 23:22:48 +0530
>> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
>>
>>> On 9/18/2018 5:04 AM, Steven Rostedt wrote:
>>>>
>>>> It looks like pstore_event_call() gets called from a trace event. You
>>>> can't call kmalloc() from one. One thing is that kmalloc has
>>>> tracepoints itself. You trace those you just entered an infinite loop.
>>>>
>>>
>>> Ok will remove it in v2. But any alternative way to do this?
>>
>> I think I describe it below.
>>
> 
> Ok got it, will change and post the 2nd version soon.
> 

Hi Steven,

Instead of dummy iterator, can't we have something like below, there 
won't be any infinite loop if we trace kmalloc in this case. This is 
same as tp_printk.

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 018cbbefb769..271b0573f44a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8644,8 +8644,14 @@ void __init early_trace_init(void)
                         static_key_enable(&tracepoint_printk_key.key);
         }

-       if (tracepoint_pstore)
-               static_key_enable(&tracepoint_pstore_key.key);
+       if (tracepoint_pstore) {
+               tracepoint_pstore_iter =
+                       kmalloc(sizeof(*tracepoint_pstore_iter), 
GFP_KERNEL);
+               if (WARN_ON(!tracepoint_pstore_iter))
+                       tracepoint_pstore = 0;
+               else
+                       static_key_enable(&tracepoint_pstore_key.key);
+       }

         tracer_alloc_buffers();
  }
diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
index f5263b6fb96f..0534546aef6d 100644
--- a/fs/pstore/ftrace.c
+++ b/fs/pstore/ftrace.c
@@ -73,7 +73,6 @@ void notrace pstore_event_call(struct 
trace_event_buffer *fbuffer)
         struct trace_event *event;
         struct seq_buf *seq;
         unsigned long flags;
-       gfp_t gfpflags;

         if (!psinfo)

         if (!psinfo)
                 return;
@@ -81,20 +80,17 @@ void notrace pstore_event_call(struct 
trace_event_buffer *fbuffer)
         if (unlikely(oops_in_progress))
                 return;

-       pstore_record_init(&record, psinfo);
-       record.type = PSTORE_TYPE_EVENT;
-
-       /* Can be called in atomic context */
-       gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC : 
GFP_KERNEL;
-
-       iter = kmalloc(sizeof(*iter), gfpflags);
+       iter = tracepoint_pstore_iter;
         if (!iter)
                 return;

+       pstore_record_init(&record, psinfo);
+       record.type = PSTORE_TYPE_EVENT;
+
         event_call = fbuffer->trace_file->event_call;
         if (!event_call || !event_call->event.funcs ||
             !event_call->event.funcs->trace)
-               goto fail_event;
+               return;

         event = &fbuffer->trace_file->event_call->event;

@@ -116,9 +112,6 @@ void notrace pstore_event_call(struct 
trace_event_buffer *fbuffer)
         psinfo->write(&record);

         spin_unlock_irqrestore(&psinfo->buf_lock, flags);
-
-fail_event:
-       kfree(iter);
  }

Thanks,
Sai

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Joel Fernandes]

On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
<saiprakash.ranjan@codeaurora.org> wrote:
>
> Currently pstore has function trace support which can be
> used to get the function call chain with limited data.
> Event tracing has extra data which is useful to debug wide
> variety of issues and is heavily used across the kernel.
>
[...]
> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
> ---
>  fs/pstore/Kconfig          |  2 +-
>  fs/pstore/ftrace.c         | 55 ++++++++++++++++++++++++++++++++++++++
>  fs/pstore/inode.c          |  4 +++
>  fs/pstore/ram.c            | 44 +++++++++++++++++++++++++++---
>  include/linux/pstore.h     |  2 ++
>  include/linux/pstore_ram.h |  1 +
>  6 files changed, 104 insertions(+), 4 deletions(-)
>
> diff --git a/fs/pstore/Kconfig b/fs/pstore/Kconfig
> index 503086f7f7c1..6fe087b13a51 100644
> --- a/fs/pstore/Kconfig
> +++ b/fs/pstore/Kconfig
> @@ -126,7 +126,7 @@ config PSTORE_PMSG
>
>  config PSTORE_FTRACE
>         bool "Persistent function tracer"
> -       depends on PSTORE
> +       depends on PSTORE && PSTORE!=m
>         depends on FUNCTION_TRACER
>         depends on DEBUG_FS
>         help
> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
> index 06aab07b6bb7..d47dc93ac098 100644
> --- a/fs/pstore/ftrace.c
> +++ b/fs/pstore/ftrace.c
> @@ -24,6 +24,8 @@
>  #include <linux/debugfs.h>
>  #include <linux/err.h>
>  #include <linux/cache.h>
> +#include <linux/slab.h>
> +#include <linux/trace_events.h>
>  #include <asm/barrier.h>
>  #include "internal.h"
>
> @@ -62,6 +64,59 @@ static struct ftrace_ops pstore_ftrace_ops __read_mostly = {
>         .func   = pstore_ftrace_call,
>  };
>
> +void notrace pstore_event_call(struct trace_event_buffer *fbuffer)
> +{
> +       struct trace_iterator *iter;
> +       struct trace_seq *s;
> +       struct trace_event_call *event_call;
> +       struct pstore_record record;
> +       struct trace_event *event;
> +       struct seq_buf *seq;
> +       unsigned long flags;
> +
> +       if (!psinfo)
> +               return;
> +
> +       if (unlikely(oops_in_progress))
> +               return;
> +
> +       pstore_record_init(&record, psinfo);
> +       record.type = PSTORE_TYPE_EVENT;
> +
> +       iter = kmalloc(sizeof(*iter), GFP_KERNEL);
> +       if (!iter)
> +               return;
> +
> +       event_call = fbuffer->trace_file->event_call;
> +       if (!event_call || !event_call->event.funcs ||
> +           !event_call->event.funcs->trace)
> +               goto fail_event;
> +
> +       event = &fbuffer->trace_file->event_call->event;
> +
> +       spin_lock_irqsave(&psinfo->buf_lock, flags);

Could you just split the pstore space into a per-cpu event buffer like
we are doing for ftrace-on-pstore? Then you don't need to lock. I fear
the lock contention will be apparent. The pstore code already has
plumbing to split the store buffer per CPU.

Also I think this spinlock can be moved further down.

> +
> +       trace_seq_init(&iter->seq);
> +       iter->ent = fbuffer->entry;
> +       event_call->event.funcs->trace(iter, 0, event);
> +       trace_seq_putc(&iter->seq, 0);

Would it be possible to store the binary trace record in the pstore
buffer instead of outputting text? I suspect that will both be faster
and less space.

> +
> +       if (seq->size > psinfo->bufsize)
> +               seq->size = psinfo->bufsize;
> +
> +       s = &iter->seq;
> +       seq = &s->seq;
> +
> +       record.buf = (char *)(seq->buffer);
> +       record.size = seq->len;
> +       psinfo->write(&record);

thanks,

 - Joel

> +
> +       spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> +
> +fail_event:
> +       kfree(iter);
> +}
> +
>  static DEFINE_MUTEX(pstore_ftrace_lock);
>  static bool pstore_ftrace_enabled;
>
> diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
> index 5fcb845b9fec..f099152abbbd 100644
> --- a/fs/pstore/inode.c
> +++ b/fs/pstore/inode.c
> @@ -345,6 +345,10 @@ int pstore_mkfile(struct dentry *root, struct pstore_record *record)
>                 scnprintf(name, sizeof(name), "console-%s-%llu",
>                           record->psi->name, record->id);
>                 break;
> +       case PSTORE_TYPE_EVENT:
> +               scnprintf(name, sizeof(name), "event-%s-%llu",
> +                         record->psi->name, record->id);
> +               break;
>         case PSTORE_TYPE_FTRACE:
>                 scnprintf(name, sizeof(name), "ftrace-%s-%llu",
>                           record->psi->name, record->id);
> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
> index bbd1e357c23d..f60d41c0309e 100644
> --- a/fs/pstore/ram.c
> +++ b/fs/pstore/ram.c
> @@ -48,6 +48,10 @@ static ulong ramoops_console_size = MIN_MEM_SIZE;
>  module_param_named(console_size, ramoops_console_size, ulong, 0400);
>  MODULE_PARM_DESC(console_size, "size of kernel console log");
>
> +static ulong ramoops_event_size = MIN_MEM_SIZE;
> +module_param_named(event_size, ramoops_event_size, ulong, 0400);
> +MODULE_PARM_DESC(event_size, "size of event log");
> +
>  static ulong ramoops_ftrace_size = MIN_MEM_SIZE;
>  module_param_named(ftrace_size, ramoops_ftrace_size, ulong, 0400);
>  MODULE_PARM_DESC(ftrace_size, "size of ftrace log");
> @@ -86,6 +90,7 @@ MODULE_PARM_DESC(ramoops_ecc,
>  struct ramoops_context {
>         struct persistent_ram_zone **dprzs;     /* Oops dump zones */
>         struct persistent_ram_zone *cprz;       /* Console zone */
> +       struct persistent_ram_zone *eprz;       /* Event zone */
>         struct persistent_ram_zone **fprzs;     /* Ftrace zones */
>         struct persistent_ram_zone *mprz;       /* PMSG zone */
>         phys_addr_t phys_addr;
> @@ -93,6 +98,7 @@ struct ramoops_context {
>         unsigned int memtype;
>         size_t record_size;
>         size_t console_size;
> +       size_t event_size;
>         size_t ftrace_size;
>         size_t pmsg_size;
>         int dump_oops;
> @@ -103,6 +109,7 @@ struct ramoops_context {
>         /* _read_cnt need clear on ramoops_pstore_open */
>         unsigned int dump_read_cnt;
>         unsigned int console_read_cnt;
> +       unsigned int event_read_cnt;
>         unsigned int max_ftrace_cnt;
>         unsigned int ftrace_read_cnt;
>         unsigned int pmsg_read_cnt;
> @@ -118,6 +125,7 @@ static int ramoops_pstore_open(struct pstore_info *psi)
>
>         cxt->dump_read_cnt = 0;
>         cxt->console_read_cnt = 0;
> +       cxt->event_read_cnt = 0;
>         cxt->ftrace_read_cnt = 0;
>         cxt->pmsg_read_cnt = 0;
>         return 0;
> @@ -277,6 +285,11 @@ static ssize_t ramoops_pstore_read(struct pstore_record *record)
>                                            1, &record->id, &record->type,
>                                            PSTORE_TYPE_CONSOLE, 0);
>
> +       if (!prz_ok(prz))
> +               prz = ramoops_get_next_prz(&cxt->eprz, &cxt->event_read_cnt,
> +                                          1, &record->id, &record->type,
> +                                          PSTORE_TYPE_EVENT, 0);
> +
>         if (!prz_ok(prz))
>                 prz = ramoops_get_next_prz(&cxt->mprz, &cxt->pmsg_read_cnt,
>                                            1, &record->id, &record->type,
> @@ -385,6 +398,11 @@ static int notrace ramoops_pstore_write(struct pstore_record *record)
>                         return -ENOMEM;
>                 persistent_ram_write(cxt->cprz, record->buf, record->size);
>                 return 0;
> +       } else if (record->type == PSTORE_TYPE_EVENT) {
> +               if (!cxt->eprz)
> +                       return -ENOMEM;
> +               persistent_ram_write(cxt->eprz, record->buf, record->size);
> +               return 0;
>         } else if (record->type == PSTORE_TYPE_FTRACE) {
>                 int zonenum;
>
> @@ -475,6 +493,9 @@ static int ramoops_pstore_erase(struct pstore_record *record)
>         case PSTORE_TYPE_CONSOLE:
>                 prz = cxt->cprz;
>                 break;
> +       case PSTORE_TYPE_EVENT:
> +               prz = cxt->eprz;
> +               break;
>         case PSTORE_TYPE_FTRACE:
>                 if (record->id >= cxt->max_ftrace_cnt)
>                         return -EINVAL;
> @@ -699,6 +720,7 @@ static int ramoops_parse_dt(struct platform_device *pdev,
>
>         parse_size("record-size", pdata->record_size);
>         parse_size("console-size", pdata->console_size);
> +       parse_size("event-size", pdata->event_size);
>         parse_size("ftrace-size", pdata->ftrace_size);
>         parse_size("pmsg-size", pdata->pmsg_size);
>         parse_size("ecc-size", pdata->ecc_info.ecc_size);
> @@ -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->event_size && !pdata->ftrace_size &&
> +                       !pdata->pmsg_size)) {
>                 pr_err("The memory size and the record/console size must be "
>                         "non-zero\n");
>                 goto fail_out;
> @@ -757,6 +780,8 @@ static int ramoops_probe(struct platform_device *pdev)
>                 pdata->record_size = rounddown_pow_of_two(pdata->record_size);
>         if (pdata->console_size && !is_power_of_2(pdata->console_size))
>                 pdata->console_size = rounddown_pow_of_two(pdata->console_size);
> +       if (pdata->event_size && !is_power_of_2(pdata->event_size))
> +               pdata->event_size = rounddown_pow_of_two(pdata->event_size);
>         if (pdata->ftrace_size && !is_power_of_2(pdata->ftrace_size))
>                 pdata->ftrace_size = rounddown_pow_of_two(pdata->ftrace_size);
>         if (pdata->pmsg_size && !is_power_of_2(pdata->pmsg_size))
> @@ -767,6 +792,7 @@ static int ramoops_probe(struct platform_device *pdev)
>         cxt->memtype = pdata->mem_type;
>         cxt->record_size = pdata->record_size;
>         cxt->console_size = pdata->console_size;
> +       cxt->event_size = pdata->event_size;
>         cxt->ftrace_size = pdata->ftrace_size;
>         cxt->pmsg_size = pdata->pmsg_size;
>         cxt->dump_oops = pdata->dump_oops;
> @@ -775,8 +801,8 @@ 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;
> +       dump_mem_sz = cxt->size - cxt->console_size - cxt->event_size
> +                       - cxt->ftrace_size - cxt->pmsg_size;
>         err = ramoops_init_przs("dump", dev, cxt, &cxt->dprzs, &paddr,
>                                 dump_mem_sz, cxt->record_size,
>                                 &cxt->max_dump_cnt, 0, 0);
> @@ -788,6 +814,11 @@ static int ramoops_probe(struct platform_device *pdev)
>         if (err)
>                 goto fail_init_cprz;
>
> +       err = ramoops_init_prz("event", dev, cxt, &cxt->eprz, &paddr,
> +                              cxt->event_size, 0);
> +       if (err)
> +               goto fail_init_eprz;
> +
>         cxt->max_ftrace_cnt = (cxt->flags & RAMOOPS_FLAG_FTRACE_PER_CPU)
>                                 ? nr_cpu_ids
>                                 : 1;
> @@ -825,6 +856,8 @@ static int ramoops_probe(struct platform_device *pdev)
>         cxt->pstore.flags = PSTORE_FLAGS_DMESG;
>         if (cxt->console_size)
>                 cxt->pstore.flags |= PSTORE_FLAGS_CONSOLE;
> +       if (cxt->event_size)
> +               cxt->pstore.flags |= PSTORE_FLAGS_EVENT;
>         if (cxt->ftrace_size)
>                 cxt->pstore.flags |= PSTORE_FLAGS_FTRACE;
>         if (cxt->pmsg_size)
> @@ -845,6 +878,7 @@ static int ramoops_probe(struct platform_device *pdev)
>         record_size = pdata->record_size;
>         dump_oops = pdata->dump_oops;
>         ramoops_console_size = pdata->console_size;
> +       ramoops_event_size = pdata->event_size;
>         ramoops_pmsg_size = pdata->pmsg_size;
>         ramoops_ftrace_size = pdata->ftrace_size;
>
> @@ -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->eprz);
> +fail_init_eprz:
>         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->eprz);
>         persistent_ram_free(cxt->mprz);
>         persistent_ram_free(cxt->cprz);
>         ramoops_free_przs(cxt);
> @@ -916,6 +953,7 @@ static void ramoops_register_dummy(void)
>         dummy_data->mem_type = mem_type;
>         dummy_data->record_size = record_size;
>         dummy_data->console_size = ramoops_console_size;
> +       dummy_data->event_size = ramoops_event_size;
>         dummy_data->ftrace_size = ramoops_ftrace_size;
>         dummy_data->pmsg_size = ramoops_pmsg_size;
>         dummy_data->dump_oops = dump_oops;
> diff --git a/include/linux/pstore.h b/include/linux/pstore.h
> index a15bc4d48752..c31bb9567b4a 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_EVENT       = 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_EVENT     (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..f01055c6cc40 100644
> --- a/include/linux/pstore_ram.h
> +++ b/include/linux/pstore_ram.h
> @@ -95,6 +95,7 @@ struct ramoops_platform_data {
>         unsigned int    mem_type;
>         unsigned long   record_size;
>         unsigned long   console_size;
> +       unsigned long   event_size;
>         unsigned long   ftrace_size;
>         unsigned long   pmsg_size;
>         int             dump_oops;
> --
> QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
> of Code Aurora Forum, hosted by The Linux Foundation
>

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/22/2018 2:35 PM, Joel Fernandes wrote:
> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
> <saiprakash.ranjan@codeaurora.org> wrote:
>>
> Could you just split the pstore space into a per-cpu event buffer like
> we are doing for ftrace-on-pstore? Then you don't need to lock. I fear
> the lock contention will be apparent. The pstore code already has
> plumbing to split the store buffer per CPU.
> 

Hi Joel,

Thanks a lot for reviewing.

I just looked at per-cpu buffer for ftrace and itseems the pstore percpu 
records will need to be merged into one record if we add this support 
for events. Merging of ftrace logs is based on timestamp, but for events 
we do not have timestamp field (for this specific reason I have added 
timestamp field for IO event tracing so that atleast we can know the cpu 
number in pstore output). For example, the sched event pstore output 
below has no timestamp field, so how do we merge per-cpu logs?

# tail /sys/fs/pstore/event-ramoops-0
sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=002
sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=002

Also Pstore ftrace log format is fixed i.e.,(CPU:%d ts:%llu %08lx  %08lx 
  %pf <- %pF\n"), but different events will have different formats and 
we will not be able to add timestamp field like how pstore ftrace does 
using  pstore_ftrace_write_timestamp() and pstore_ftrace_read_timestamp().

Sorry if I am confusing you, I can explain better I guess.

> Also I think this spinlock can be moved further down.
> 

OK. Something like this would suffice?

{{{
spin_lock_irqsave(&psinfo->buf_lock, flags);

record.buf = (char *)(seq->buffer);
record.size = seq->len;
psinfo->write(&record);

spin_unlock_irqrestore(&psinfo->buf_lock, flags);
}}}

>> +
>> +       trace_seq_init(&iter->seq);
>> +       iter->ent = fbuffer->entry;
>> +       event_call->event.funcs->trace(iter, 0, event);
>> +       trace_seq_putc(&iter->seq, 0);
> 
> Would it be possible to store the binary trace record in the pstore
> buffer instead of outputting text? I suspect that will both be faster
> and less space.
> 

I will try this and come back.

Thanks,
Sai

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>> Could you just split the pstore space into a per-cpu event buffer like
>> we are doing for ftrace-on-pstore? Then you don't need to lock. I fear
>> the lock contention will be apparent. The pstore code already has
>> plumbing to split the store buffer per CPU.
>>
> 
> Hi Joel,
> 
> Thanks a lot for reviewing.
> 
> I just looked at per-cpu buffer for ftrace and itseems the pstore percpu 
> records will need to be merged into one record if we add this support 
> for events. Merging of ftrace logs is based on timestamp, but for events 
> we do not have timestamp field (for this specific reason I have added 
> timestamp field for IO event tracing so that atleast we can know the cpu 
> number in pstore output). For example, the sched event pstore output 
> below has no timestamp field, so how do we merge per-cpu logs?
> 
> # tail /sys/fs/pstore/event-ramoops-0
> sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=002
> sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=002
> 
> Also Pstore ftrace log format is fixed i.e.,(CPU:%d ts:%llu %08lx  %08lx 
>   %pf <- %pF\n"), but different events will have different formats and 
> we will not be able to add timestamp field like how pstore ftrace does 
> using  pstore_ftrace_write_timestamp() and pstore_ftrace_read_timestamp().
> 
> Sorry if I am confusing you, I can explain better I guess.
> 

To add to this on db410c board with the current patch I just measured 
average throughput of dd over 60 seconds with sched event tracing 
enabled (trace_event=sched tp_pstore) : 190 MB/s

# dd if=/dev/zero of=/dev/null status=progress
11402907648 bytes (11 GB, 11 GiB) copied, 60 s, 190 MB/s^C
22430312+0 records in
22430312+0 records out
11484319744 bytes (11 GB, 11 GiB) copied, 60.4277 s, 190 MB/s

It seems fine or maybe I am testing it wrongly? Anyways let me know if I 
can test any additional things in some different ways.

Thanks,
Sai

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
> 
> 
>> Also I think this spinlock can be moved further down.
>>
> 
> OK. Something like this would suffice?
> 
> {{{
> spin_lock_irqsave(&psinfo->buf_lock, flags);
> 
> record.buf = (char *)(seq->buffer);
> record.size = seq->len;
> psinfo->write(&record);
> 
> spin_unlock_irqrestore(&psinfo->buf_lock, flags);
> }}}
> 
> 

If I move the spinlock further down like above, I get this backtrace:

[    1.367708] console [pstore-1] enabled
[    1.368874] pstore: Registered ramoops as persistent store backend
[    1.372637] ramoops: attached 0x100000@0xbff00000, ecc: 0/0
[    1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 
trace_raw_output_prep+0x18/0xa0
[    1.389416] Modules linked in:
[    1.397572] CPU: 2 PID: 2 Comm: kthreadd Not tainted 
4.19.0-rc4-00032-g71e30ed20433-dirty #9
[    1.409122] pstate: 80000005 (Nzcv daif -PAN -UAO)
[    1.415804] pc : trace_raw_output_prep+0x18/0xa0
[    1.420404] lr : trace_raw_output_sched_process_fork+0x1c/0x70
[    1.425176] sp : ffff00000803bc00
[    1.430815] x29: ffff00000803bc00 x28: ffff80003ca68d80
[    1.434204] x27: ffff00000810d000 x26: 0000000000000001
[    1.439586] x25: 0000000000000000 x24: ffff80000eb05090
[    1.444881] x23: ffff80003ca68d80 x22: ffff00000803bd58
[    1.450176] x21: ffff000009e63000 x20: ffff80003cbf8988
[    1.455470] x19: ffff80000eb04000 x18: ffffffffffffffff
[    1.460766] x17: 000000000006df2c x16: 0000000000000000
[    1.466061] x15: ffff000009b496c8 x14: 0000000000000040
[    1.471356] x13: ffffffffffffffff x12: 0000000000000000
[    1.476651] x11: ffff80003c49a6a8 x10: 00000000000005d8
[    1.481947] x9 : ffff80003c89f400 x8 : ffff00000803bc60
[    1.487242] x7 : 0000000000000034 x6 : 0000000005d97d4a
[    1.492536] x5 : 00ffffffffffffff x4 : 0000000000000050
[    1.497831] x3 : 0000000000000056 x2 : ffff000009b657a0
[    1.503127] x1 : ffff000009b657c0 x0 : ffff80000eb04000
[    1.508422] Call trace:
[    1.513716]  trace_raw_output_prep+0x18/0xa0
[    1.515890]  pstore_event_call+0xbc/0x130
[    1.520402]  trace_event_buffer_commit+0xf8/0x248
[    1.524308]  trace_event_raw_event_sched_process_fork+0xc0/0xf8
[    1.528999]  _do_fork+0x234/0x418
[    1.534724]  kernel_thread+0x48/0x58
[    1.538196]  kthreadd+0x178/0x1f0
[    1.541842]  ret_from_fork+0x10/0x1c
[    1.545052] ---[ end trace 97d58905d13e7aea ]---
[    1.560654] s1: supplied by regulator-dummy
[    1.560714] s1: Bringing 0uV into 375000-375000uV

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>> +
>>> +       trace_seq_init(&iter->seq);
>>> +       iter->ent = fbuffer->entry;
>>> +       event_call->event.funcs->trace(iter, 0, event);
>>> +       trace_seq_putc(&iter->seq, 0);
>>
>> Would it be possible to store the binary trace record in the pstore
>> buffer instead of outputting text? I suspect that will both be faster
>> and less space.
>>
> 
> I will try this and come back.
> 

Hi Joel,

I removed trace_seq_putc and there is some improvement seen: 203 MB/s

# dd if=/dev/zero of=/dev/null status=progress
12207371264 bytes (12 GB, 11 GiB) copied, 60 s, 203 MB/s^C
24171926+0 records in
24171926+0 records out
12376026112 bytes (12 GB, 12 GiB) copied, 60.8282 s, 203 MB/s

This seems good when compared to 190 MB/s seen previously.
If this is Ok, then I will spin v2 with changes suggested.

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

Re: [PATCH 2/6] pstore: Add event tracing support

[Joel Fernandes]

On Sun, Sep 23, 2018 at 8:33 AM, Sai Prakash Ranjan
<saiprakash.ranjan@codeaurora.org> wrote:
> On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
>>
>> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>>>
>>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>>
>>>>
>>>> +
>>>> +       trace_seq_init(&iter->seq);
>>>> +       iter->ent = fbuffer->entry;
>>>> +       event_call->event.funcs->trace(iter, 0, event);
>>>> +       trace_seq_putc(&iter->seq, 0);
>>>
>>>
>>> Would it be possible to store the binary trace record in the pstore
>>> buffer instead of outputting text? I suspect that will both be faster
>>> and less space.
>>>
>>
>> I will try this and come back.
>>
>
> Hi Joel,
>
> I removed trace_seq_putc and there is some improvement seen: 203 MB/s
>
> # dd if=/dev/zero of=/dev/null status=progress
> 12207371264 bytes (12 GB, 11 GiB) copied, 60 s, 203 MB/s^C
> 24171926+0 records in
> 24171926+0 records out
> 12376026112 bytes (12 GB, 12 GiB) copied, 60.8282 s, 203 MB/s
>
> This seems good when compared to 190 MB/s seen previously.
> If this is Ok, then I will spin v2 with changes suggested.

Sorry for slow reply, yes that sounds good and a worthwhile perf improvement.

thanks,

 - Joel

Re: [PATCH 2/6] pstore: Add event tracing support

[Joel Fernandes]

On Tue, Sep 25, 2018 at 1:37 PM, Joel Fernandes <joelaf@google.com> wrote:
> On Sun, Sep 23, 2018 at 8:33 AM, Sai Prakash Ranjan
> <saiprakash.ranjan@codeaurora.org> wrote:
>> On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
>>>
>>> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>>>>
>>>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>>>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>>>
>>>>>
>>>>> +
>>>>> +       trace_seq_init(&iter->seq);
>>>>> +       iter->ent = fbuffer->entry;
>>>>> +       event_call->event.funcs->trace(iter, 0, event);
>>>>> +       trace_seq_putc(&iter->seq, 0);
>>>>
>>>>
>>>> Would it be possible to store the binary trace record in the pstore
>>>> buffer instead of outputting text? I suspect that will both be faster
>>>> and less space.
>>>>
>>>
>>> I will try this and come back.
>>>
>>
>> Hi Joel,
>>
>> I removed trace_seq_putc and there is some improvement seen: 203 MB/s
>>
>> # dd if=/dev/zero of=/dev/null status=progress
>> 12207371264 bytes (12 GB, 11 GiB) copied, 60 s, 203 MB/s^C
>> 24171926+0 records in
>> 24171926+0 records out
>> 12376026112 bytes (12 GB, 12 GiB) copied, 60.8282 s, 203 MB/s
>>
>> This seems good when compared to 190 MB/s seen previously.
>> If this is Ok, then I will spin v2 with changes suggested.
>
> Sorry for slow reply, yes that sounds good and a worthwhile perf improvement.
>

Well so I think you should still not use spinlock to synchronize and
split the buffer. You could expand pstore_record to have a ts field or
introduce a new API like ->write_percpu instead of write, or
something. But I strongly feel you should lock. For ftrace function
trace, the perf reduction with locking was dramatic.

- Joel

Re: [PATCH 2/6] pstore: Add event tracing support

[Joel Fernandes]

On Tue, Sep 25, 2018 at 1:39 PM, Joel Fernandes <joelaf@google.com> wrote:
> On Tue, Sep 25, 2018 at 1:37 PM, Joel Fernandes <joelaf@google.com> wrote:
>> On Sun, Sep 23, 2018 at 8:33 AM, Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
>>> On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
>>>>
>>>> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>>>>>
>>>>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>>>>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>>>>
>>>>>>
>>>>>> +
>>>>>> +       trace_seq_init(&iter->seq);
>>>>>> +       iter->ent = fbuffer->entry;
>>>>>> +       event_call->event.funcs->trace(iter, 0, event);
>>>>>> +       trace_seq_putc(&iter->seq, 0);
>>>>>
>>>>>
>>>>> Would it be possible to store the binary trace record in the pstore
>>>>> buffer instead of outputting text? I suspect that will both be faster
>>>>> and less space.
>>>>>
>>>>
>>>> I will try this and come back.
>>>>
>>>
>>> Hi Joel,
>>>
>>> I removed trace_seq_putc and there is some improvement seen: 203 MB/s
>>>
>>> # dd if=/dev/zero of=/dev/null status=progress
>>> 12207371264 bytes (12 GB, 11 GiB) copied, 60 s, 203 MB/s^C
>>> 24171926+0 records in
>>> 24171926+0 records out
>>> 12376026112 bytes (12 GB, 12 GiB) copied, 60.8282 s, 203 MB/s
>>>
>>> This seems good when compared to 190 MB/s seen previously.
>>> If this is Ok, then I will spin v2 with changes suggested.
>>
>> Sorry for slow reply, yes that sounds good and a worthwhile perf improvement.
>>
>
> Well so I think you should still not use spinlock to synchronize and
> split the buffer. You could expand pstore_record to have a ts field or
> introduce a new API like ->write_percpu instead of write, or
> something. But I strongly feel you should lock. For ftrace function

Aargh, I meant you should *not* lock :-)

Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan]

On 9/26/2018 2:10 AM, Joel Fernandes wrote:
> On Tue, Sep 25, 2018 at 1:39 PM, Joel Fernandes <joelaf@google.com> wrote:
>> On Tue, Sep 25, 2018 at 1:37 PM, Joel Fernandes <joelaf@google.com> wrote:
>>> On Sun, Sep 23, 2018 at 8:33 AM, Sai Prakash Ranjan
>>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>> On 9/22/2018 10:07 PM, Sai Prakash Ranjan wrote:
>>>>>
>>>>> On 9/22/2018 2:35 PM, Joel Fernandes wrote:
>>>>>>
>>>>>> On Sat, Sep 8, 2018 at 4:28 PM Sai Prakash Ranjan
>>>>>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>>>>>
>>>>>>>
>>>>>>> +
>>>>>>> +       trace_seq_init(&iter->seq);
>>>>>>> +       iter->ent = fbuffer->entry;
>>>>>>> +       event_call->event.funcs->trace(iter, 0, event);
>>>>>>> +       trace_seq_putc(&iter->seq, 0);
>>>>>>
>>>>>>
>>>>>> Would it be possible to store the binary trace record in the pstore
>>>>>> buffer instead of outputting text? I suspect that will both be faster
>>>>>> and less space.
>>>>>>
>>>>>
>>>>> I will try this and come back.
>>>>>
>>>>
>>>> Hi Joel,
>>>>
>>>> I removed trace_seq_putc and there is some improvement seen: 203 MB/s
>>>>
>>>> # dd if=/dev/zero of=/dev/null status=progress
>>>> 12207371264 bytes (12 GB, 11 GiB) copied, 60 s, 203 MB/s^C
>>>> 24171926+0 records in
>>>> 24171926+0 records out
>>>> 12376026112 bytes (12 GB, 12 GiB) copied, 60.8282 s, 203 MB/s
>>>>
>>>> This seems good when compared to 190 MB/s seen previously.
>>>> If this is Ok, then I will spin v2 with changes suggested.
>>>
>>> Sorry for slow reply, yes that sounds good and a worthwhile perf improvement.
>>>
>>
>> Well so I think you should still not use spinlock to synchronize and
>> split the buffer. You could expand pstore_record to have a ts field or
>> introduce a new API like ->write_percpu instead of write, or
>> something. But I strongly feel you should lock. For ftrace function
> 
> Aargh, I meant you should *not* lock :-)
> 

OK I can try this and will measure some perf difference.

BTW I guess you missed my previous comment about not able to combine 
logs based on timestamp? Anyways I think if I add some extra ts field, 
then should be able to do it.

Thanks,
Sai

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

[PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Sai Prakash Ranjan]

Add the kernel command line tp_pstore option that will have
tracepoints go to persistent ram buffer as well as to the
trace buffer for further debugging. This is similar to tp_printk
cmdline option of ftrace.

Pstore support for event tracing is already added and we enable
logging to pstore only if cmdline is specified.

Passing "tp_pstore" will activate logging to pstore. To turn it
off, the sysctl /proc/sys/kernel/tracepoint_pstore can have '0'
echoed into it. Note, this only works if the cmdline option is
used. Echoing 1 into the sysctl file without the cmdline option
will have no affect.

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 .../admin-guide/kernel-parameters.txt         | 21 ++++++++
 include/linux/ftrace.h                        |  6 ++-
 kernel/sysctl.c                               |  7 +++
 kernel/trace/Kconfig                          | 22 +++++++-
 kernel/trace/trace.c                          | 51 +++++++++++++++++++
 kernel/trace/trace.h                          |  7 +++
 6 files changed, 112 insertions(+), 2 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 9871e649ffef..622cf64d4e5b 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -4519,6 +4519,27 @@
 			frequency tracepoints such as irq or sched, can cause
 			the system to live lock.
 
+	tp_pstore[FTRACE]
+			Have the tracepoints sent to persistent ram buffer for
+			debugging. This is useful for debugging early boot up
+			and other kernel issues where the system hangs or
+			reboots due to some unclocked access or some buggy
+			driver. Instead of spamming the console with unwanted
+			logs, we can send the logs to pstore buffer for further
+			debugging.
+
+			Last occurred events in the pstore log will be helpful
+			in identifying the reset cause.
+
+			For example, to trace sched event, add to the command
+			line:
+				trace_event=sched tp_pstore
+
+			To turn off having tracepoints sent to pstore,
+				echo 0 > /proc/sys/kernel/tracepoint_pstore
+			Note, echoing 1 into this file without the
+			tracepoint_pstore kernel cmdline option has no effect.
+
 	traceoff_on_warning
 			[FTRACE] enable this option to disable tracing when a
 			warning is hit. This turns off "tracing_on". Tracing can
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index a397907e8d72..7c3074e7ec6b 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -900,6 +900,7 @@ enum ftrace_dump_mode;
 
 extern enum ftrace_dump_mode ftrace_dump_on_oops;
 extern int tracepoint_printk;
+extern int tracepoint_pstore;
 
 extern void disable_trace_on_warning(void);
 extern int __disable_trace_on_warning;
@@ -907,9 +908,12 @@ extern int __disable_trace_on_warning;
 int tracepoint_printk_sysctl(struct ctl_table *table, int write,
 			     void __user *buffer, size_t *lenp,
 			     loff_t *ppos);
+int tracepoint_pstore_sysctl(struct ctl_table *table, int write,
+			     void __user *buffer, size_t *lenp,
+			     loff_t *ppos);
 
 #else /* CONFIG_TRACING */
-static inline void  disable_trace_on_warning(void) { }
+static inline void disable_trace_on_warning(void) { }
 #endif /* CONFIG_TRACING */
 
 #ifdef CONFIG_FTRACE_SYSCALLS
diff --git a/kernel/sysctl.c b/kernel/sysctl.c
index cc02050fd0c4..3cc1223b8955 100644
--- a/kernel/sysctl.c
+++ b/kernel/sysctl.c
@@ -653,6 +653,13 @@ static struct ctl_table kern_table[] = {
 		.mode		= 0644,
 		.proc_handler	= tracepoint_printk_sysctl,
 	},
+	{
+		.procname	= "tracepoint_pstore",
+		.data		= &tracepoint_pstore,
+		.maxlen		= sizeof(tracepoint_pstore),
+		.mode		= 0644,
+		.proc_handler	= tracepoint_pstore_sysctl,
+	},
 #endif
 #ifdef CONFIG_KEXEC_CORE
 	{
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 5e3de28c7677..d0eed268ee85 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -774,6 +774,27 @@ config TRACING_EVENTS_GPIO
 	help
 	  Enable tracing events for gpio subsystem
 
+config TRACING_EVENTS_IO
+	bool "Trace IO read/write events"
+	help
+	  Enable tracing events for IO read/write operations.
+	  This is useful for debugging random hangs or resets
+	  caused due to unclocked access or some buggy driver.
+
+	  Output of this trace event can be overwhelming and hence
+	  dynamic filtering option based on dynamic debug library
+	  is provided to narrow down the issues.
+
+	  Eg: Trace all register read/write of mmc subsystem with
+	  below command line:
+
+	    dyndbg="file drivers/mmc/* +p" trace_event=io
+
+	  See Documentation/admin-guide/dynamic-debug-howto.rst for
+	  more info on using dynamic debug.
+
+	  If unsure, say N.
+
 config GCOV_PROFILE_FTRACE
 	bool "Enable GCOV profiling on ftrace subsystem"
 	depends on GCOV_KERNEL
@@ -789,4 +810,3 @@ config GCOV_PROFILE_FTRACE
 endif # FTRACE
 
 endif # TRACING_SUPPORT
-
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index bf6f1d70484d..018cbbefb769 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -73,6 +73,11 @@ struct trace_iterator *tracepoint_print_iter;
 int tracepoint_printk;
 static DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
 
+/* Pipe tracepoints to pstore */
+struct trace_iterator *tracepoint_pstore_iter;
+int tracepoint_pstore;
+static DEFINE_STATIC_KEY_FALSE(tracepoint_pstore_key);
+
 /* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
 	{ }
@@ -238,6 +243,14 @@ static int __init set_tracepoint_printk(char *str)
 }
 __setup("tp_printk", set_tracepoint_printk);
 
+static int __init set_tracepoint_pstore(char *str)
+{
+	if ((strcmp(str, "=0") != 0 && strcmp(str, "=off") != 0))
+		tracepoint_pstore = 1;
+	return 1;
+}
+__setup("tp_pstore", set_tracepoint_pstore);
+
 unsigned long long ns2usecs(u64 nsec)
 {
 	nsec += 500;
@@ -2376,11 +2389,45 @@ int tracepoint_printk_sysctl(struct ctl_table *table, int write,
 	return ret;
 }
 
+static DEFINE_MUTEX(tracepoint_pstore_mutex);
+
+int tracepoint_pstore_sysctl(struct ctl_table *table, int write,
+			     void __user *buffer, size_t *lenp,
+			     loff_t *ppos)
+{
+	int save_tracepoint_pstore;
+	int ret;
+
+	mutex_lock(&tracepoint_pstore_mutex);
+	save_tracepoint_pstore = tracepoint_pstore;
+
+	ret = proc_dointvec(table, write, buffer, lenp, ppos);
+
+	if (!tracepoint_pstore_iter)
+		tracepoint_pstore = 0;
+
+	if (save_tracepoint_pstore == tracepoint_pstore)
+		goto out;
+
+	if (tracepoint_pstore)
+		static_key_enable(&tracepoint_pstore_key.key);
+	else
+		static_key_disable(&tracepoint_pstore_key.key);
+
+ out:
+	mutex_unlock(&tracepoint_pstore_mutex);
+
+	return ret;
+}
+
 void trace_event_buffer_commit(struct trace_event_buffer *fbuffer)
 {
 	if (static_key_false(&tracepoint_printk_key.key))
 		output_printk(fbuffer);
 
+	if (static_key_false(&tracepoint_pstore_key.key))
+		pstore_event_call(fbuffer);
+
 	event_trigger_unlock_commit(fbuffer->trace_file, fbuffer->buffer,
 				    fbuffer->event, fbuffer->entry,
 				    fbuffer->flags, fbuffer->pc);
@@ -8596,6 +8643,10 @@ void __init early_trace_init(void)
 		else
 			static_key_enable(&tracepoint_printk_key.key);
 	}
+
+	if (tracepoint_pstore)
+		static_key_enable(&tracepoint_pstore_key.key);
+
 	tracer_alloc_buffers();
 }
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 3b8c0e24ab30..edc28d0c27eb 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1843,5 +1843,12 @@ static inline void tracer_hardirqs_off(unsigned long a0, unsigned long a1) { }
 #endif
 
 extern struct trace_iterator *tracepoint_print_iter;
+extern struct trace_iterator *tracepoint_pstore_iter;
+
+#ifdef CONFIG_PSTORE_FTRACE
+extern void pstore_event_call(struct trace_event_buffer *fbuffer);
+#else
+static inline void pstore_event_call(struct trace_event_buffer *fbuffer) { }
+#endif
 
 #endif /* _LINUX_KERNEL_TRACE_H */
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Joel Fernandes]

On Sat, Sep 8, 2018 at 1:28 PM Sai Prakash Ranjan
<saiprakash.ranjan@codeaurora.org> wrote:
>
> Add the kernel command line tp_pstore option that will have
> tracepoints go to persistent ram buffer as well as to the
> trace buffer for further debugging. This is similar to tp_printk
> cmdline option of ftrace.
>
> Pstore support for event tracing is already added and we enable
> logging to pstore only if cmdline is specified.
>
> Passing "tp_pstore" will activate logging to pstore. To turn it
> off, the sysctl /proc/sys/kernel/tracepoint_pstore can have '0'
> echoed into it. Note, this only works if the cmdline option is
> used. Echoing 1 into the sysctl file without the cmdline option
> will have no affect.
>
> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
> ---
>  .../admin-guide/kernel-parameters.txt         | 21 ++++++++
>  include/linux/ftrace.h                        |  6 ++-
>  kernel/sysctl.c                               |  7 +++
>  kernel/trace/Kconfig                          | 22 +++++++-
>  kernel/trace/trace.c                          | 51 +++++++++++++++++++
>  kernel/trace/trace.h                          |  7 +++
>  6 files changed, 112 insertions(+), 2 deletions(-)
>
[...]
>  config GCOV_PROFILE_FTRACE
>         bool "Enable GCOV profiling on ftrace subsystem"
>         depends on GCOV_KERNEL
> @@ -789,4 +810,3 @@ config GCOV_PROFILE_FTRACE
>  endif # FTRACE
>
>  endif # TRACING_SUPPORT
> -
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index bf6f1d70484d..018cbbefb769 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -73,6 +73,11 @@ struct trace_iterator *tracepoint_print_iter;
>  int tracepoint_printk;
>  static DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
>
> +/* Pipe tracepoints to pstore */
> +struct trace_iterator *tracepoint_pstore_iter;
> +int tracepoint_pstore;
> +static DEFINE_STATIC_KEY_FALSE(tracepoint_pstore_key);
> +
>  /* For tracers that don't implement custom flags */
>  static struct tracer_opt dummy_tracer_opt[] = {
>         { }
> @@ -238,6 +243,14 @@ static int __init set_tracepoint_printk(char *str)
>  }
>  __setup("tp_printk", set_tracepoint_printk);
>
> +static int __init set_tracepoint_pstore(char *str)
> +{
> +       if ((strcmp(str, "=0") != 0 && strcmp(str, "=off") != 0))
> +               tracepoint_pstore = 1;
> +       return 1;
> +}
> +__setup("tp_pstore", set_tracepoint_pstore);
> +
>  unsigned long long ns2usecs(u64 nsec)
>  {
>         nsec += 500;
> @@ -2376,11 +2389,45 @@ int tracepoint_printk_sysctl(struct ctl_table *table, int write,
>         return ret;
>  }
>
> +static DEFINE_MUTEX(tracepoint_pstore_mutex);
> +
> +int tracepoint_pstore_sysctl(struct ctl_table *table, int write,
> +                            void __user *buffer, size_t *lenp,
> +                            loff_t *ppos)
> +{
> +       int save_tracepoint_pstore;
> +       int ret;
> +
> +       mutex_lock(&tracepoint_pstore_mutex);
> +       save_tracepoint_pstore = tracepoint_pstore;
> +
> +       ret = proc_dointvec(table, write, buffer, lenp, ppos);
> +
> +       if (!tracepoint_pstore_iter)
> +               tracepoint_pstore = 0;
> +
> +       if (save_tracepoint_pstore == tracepoint_pstore)
> +               goto out;
> +
> +       if (tracepoint_pstore)
> +               static_key_enable(&tracepoint_pstore_key.key);
> +       else
> +               static_key_disable(&tracepoint_pstore_key.key);
> +
> + out:
> +       mutex_unlock(&tracepoint_pstore_mutex);
> +
> +       return ret;
> +}
> +
>  void trace_event_buffer_commit(struct trace_event_buffer *fbuffer)
>  {
>         if (static_key_false(&tracepoint_printk_key.key))
>                 output_printk(fbuffer);
>
> +       if (static_key_false(&tracepoint_pstore_key.key))
> +               pstore_event_call(fbuffer);

Can you not find a way to pass the size of the even record here, to
pstore? Then you can directly allocate and store the binary record in
pstore itself instead of rendering and storing the text in pstore
which will be more space (and I think time) efficient. I also think if
you do this, then you will not need to use the spinlock in the pstore
(which AIUI is preventing the warning you're seeing in the
event_call->event.funcs->trace() call).

- Joel

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Sai Prakash Ranjan]

On 9/26/2018 2:55 AM, Joel Fernandes wrote:
> On Sat, Sep 8, 2018 at 1:28 PM Sai Prakash Ranjan
> <saiprakash.ranjan@codeaurora.org> wrote:
>>
>> Add the kernel command line tp_pstore option that will have
>> tracepoints go to persistent ram buffer as well as to the
>> trace buffer for further debugging. This is similar to tp_printk
>> cmdline option of ftrace.
>>
>> Pstore support for event tracing is already added and we enable
>> logging to pstore only if cmdline is specified.
>>
>> Passing "tp_pstore" will activate logging to pstore. To turn it
>> off, the sysctl /proc/sys/kernel/tracepoint_pstore can have '0'
>> echoed into it. Note, this only works if the cmdline option is
>> used. Echoing 1 into the sysctl file without the cmdline option
>> will have no affect.
>>
>> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
>> ---
>>   .../admin-guide/kernel-parameters.txt         | 21 ++++++++
>>   include/linux/ftrace.h                        |  6 ++-
>>   kernel/sysctl.c                               |  7 +++
>>   kernel/trace/Kconfig                          | 22 +++++++-
>>   kernel/trace/trace.c                          | 51 +++++++++++++++++++
>>   kernel/trace/trace.h                          |  7 +++
>>   6 files changed, 112 insertions(+), 2 deletions(-)
>>
> [...]
>>   config GCOV_PROFILE_FTRACE
>>          bool "Enable GCOV profiling on ftrace subsystem"
>>          depends on GCOV_KERNEL
>> @@ -789,4 +810,3 @@ config GCOV_PROFILE_FTRACE
>>   endif # FTRACE
>>
>>   endif # TRACING_SUPPORT
>> -
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index bf6f1d70484d..018cbbefb769 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -73,6 +73,11 @@ struct trace_iterator *tracepoint_print_iter;
>>   int tracepoint_printk;
>>   static DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
>>
>> +/* Pipe tracepoints to pstore */
>> +struct trace_iterator *tracepoint_pstore_iter;
>> +int tracepoint_pstore;
>> +static DEFINE_STATIC_KEY_FALSE(tracepoint_pstore_key);
>> +
>>   /* For tracers that don't implement custom flags */
>>   static struct tracer_opt dummy_tracer_opt[] = {
>>          { }
>> @@ -238,6 +243,14 @@ static int __init set_tracepoint_printk(char *str)
>>   }
>>   __setup("tp_printk", set_tracepoint_printk);
>>
>> +static int __init set_tracepoint_pstore(char *str)
>> +{
>> +       if ((strcmp(str, "=0") != 0 && strcmp(str, "=off") != 0))
>> +               tracepoint_pstore = 1;
>> +       return 1;
>> +}
>> +__setup("tp_pstore", set_tracepoint_pstore);
>> +
>>   unsigned long long ns2usecs(u64 nsec)
>>   {
>>          nsec += 500;
>> @@ -2376,11 +2389,45 @@ int tracepoint_printk_sysctl(struct ctl_table *table, int write,
>>          return ret;
>>   }
>>
>> +static DEFINE_MUTEX(tracepoint_pstore_mutex);
>> +
>> +int tracepoint_pstore_sysctl(struct ctl_table *table, int write,
>> +                            void __user *buffer, size_t *lenp,
>> +                            loff_t *ppos)
>> +{
>> +       int save_tracepoint_pstore;
>> +       int ret;
>> +
>> +       mutex_lock(&tracepoint_pstore_mutex);
>> +       save_tracepoint_pstore = tracepoint_pstore;
>> +
>> +       ret = proc_dointvec(table, write, buffer, lenp, ppos);
>> +
>> +       if (!tracepoint_pstore_iter)
>> +               tracepoint_pstore = 0;
>> +
>> +       if (save_tracepoint_pstore == tracepoint_pstore)
>> +               goto out;
>> +
>> +       if (tracepoint_pstore)
>> +               static_key_enable(&tracepoint_pstore_key.key);
>> +       else
>> +               static_key_disable(&tracepoint_pstore_key.key);
>> +
>> + out:
>> +       mutex_unlock(&tracepoint_pstore_mutex);
>> +
>> +       return ret;
>> +}
>> +
>>   void trace_event_buffer_commit(struct trace_event_buffer *fbuffer)
>>   {
>>          if (static_key_false(&tracepoint_printk_key.key))
>>                  output_printk(fbuffer);
>>
>> +       if (static_key_false(&tracepoint_pstore_key.key))
>> +               pstore_event_call(fbuffer);
> 
> Can you not find a way to pass the size of the even record here, to
> pstore? Then you can directly allocate and store the binary record in
> pstore itself instead of rendering and storing the text in pstore
> which will be more space (and I think time) efficient. I also think if
> you do this, then you will not need to use the spinlock in the pstore
> (which AIUI is preventing the warning you're seeing in the
> event_call->event.funcs->trace() call).
> 

Right, I can check this out.

Thanks,
Sai

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

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Sai Prakash Ranjan]

On 9/26/2018 3:16 PM, Sai Prakash Ranjan wrote:
> On 9/26/2018 2:55 AM, Joel Fernandes wrote:
>> On Sat, Sep 8, 2018 at 1:28 PM Sai Prakash Ranjan
>> <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>> Add the kernel command line tp_pstore option that will have
>>> tracepoints go to persistent ram buffer as well as to the
>>> trace buffer for further debugging. This is similar to tp_printk
>>> cmdline option of ftrace.
>>>
>>> Pstore support for event tracing is already added and we enable
>>> logging to pstore only if cmdline is specified.
>>>
>>> Passing "tp_pstore" will activate logging to pstore. To turn it
>>> off, the sysctl /proc/sys/kernel/tracepoint_pstore can have '0'
>>> echoed into it. Note, this only works if the cmdline option is
>>> used. Echoing 1 into the sysctl file without the cmdline option
>>> will have no affect.
>>>
>>> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
>>> ---
>>>   .../admin-guide/kernel-parameters.txt         | 21 ++++++++
>>>   include/linux/ftrace.h                        |  6 ++-
>>>   kernel/sysctl.c                               |  7 +++
>>>   kernel/trace/Kconfig                          | 22 +++++++-
>>>   kernel/trace/trace.c                          | 51 +++++++++++++++++++
>>>   kernel/trace/trace.h                          |  7 +++
>>>   6 files changed, 112 insertions(+), 2 deletions(-)
>>>
>> [...]
>>>   config GCOV_PROFILE_FTRACE
>>>          bool "Enable GCOV profiling on ftrace subsystem"
>>>          depends on GCOV_KERNEL
>>> @@ -789,4 +810,3 @@ config GCOV_PROFILE_FTRACE
>>>   endif # FTRACE
>>>
>>>   endif # TRACING_SUPPORT
>>> -
>>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>>> index bf6f1d70484d..018cbbefb769 100644
>>> --- a/kernel/trace/trace.c
>>> +++ b/kernel/trace/trace.c
>>> @@ -73,6 +73,11 @@ struct trace_iterator *tracepoint_print_iter;
>>>   int tracepoint_printk;
>>>   static DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
>>>
>>> +/* Pipe tracepoints to pstore */
>>> +struct trace_iterator *tracepoint_pstore_iter;
>>> +int tracepoint_pstore;
>>> +static DEFINE_STATIC_KEY_FALSE(tracepoint_pstore_key);
>>> +
>>>   /* For tracers that don't implement custom flags */
>>>   static struct tracer_opt dummy_tracer_opt[] = {
>>>          { }
>>> @@ -238,6 +243,14 @@ static int __init set_tracepoint_printk(char *str)
>>>   }
>>>   __setup("tp_printk", set_tracepoint_printk);
>>>
>>> +static int __init set_tracepoint_pstore(char *str)
>>> +{
>>> +       if ((strcmp(str, "=0") != 0 && strcmp(str, "=off") != 0))
>>> +               tracepoint_pstore = 1;
>>> +       return 1;
>>> +}
>>> +__setup("tp_pstore", set_tracepoint_pstore);
>>> +
>>>   unsigned long long ns2usecs(u64 nsec)
>>>   {
>>>          nsec += 500;
>>> @@ -2376,11 +2389,45 @@ int tracepoint_printk_sysctl(struct ctl_table 
>>> *table, int write,
>>>          return ret;
>>>   }
>>>
>>> +static DEFINE_MUTEX(tracepoint_pstore_mutex);
>>> +
>>> +int tracepoint_pstore_sysctl(struct ctl_table *table, int write,
>>> +                            void __user *buffer, size_t *lenp,
>>> +                            loff_t *ppos)
>>> +{
>>> +       int save_tracepoint_pstore;
>>> +       int ret;
>>> +
>>> +       mutex_lock(&tracepoint_pstore_mutex);
>>> +       save_tracepoint_pstore = tracepoint_pstore;
>>> +
>>> +       ret = proc_dointvec(table, write, buffer, lenp, ppos);
>>> +
>>> +       if (!tracepoint_pstore_iter)
>>> +               tracepoint_pstore = 0;
>>> +
>>> +       if (save_tracepoint_pstore == tracepoint_pstore)
>>> +               goto out;
>>> +
>>> +       if (tracepoint_pstore)
>>> +               static_key_enable(&tracepoint_pstore_key.key);
>>> +       else
>>> +               static_key_disable(&tracepoint_pstore_key.key);
>>> +
>>> + out:
>>> +       mutex_unlock(&tracepoint_pstore_mutex);
>>> +
>>> +       return ret;
>>> +}
>>> +
>>>   void trace_event_buffer_commit(struct trace_event_buffer *fbuffer)
>>>   {
>>>          if (static_key_false(&tracepoint_printk_key.key))
>>>                  output_printk(fbuffer);
>>>
>>> +       if (static_key_false(&tracepoint_pstore_key.key))
>>> +               pstore_event_call(fbuffer);
>>
>> Can you not find a way to pass the size of the even record here, to
>> pstore? Then you can directly allocate and store the binary record in
>> pstore itself instead of rendering and storing the text in pstore
>> which will be more space (and I think time) efficient. I also think if
>> you do this, then you will not need to use the spinlock in the pstore
>> (which AIUI is preventing the warning you're seeing in the
>> event_call->event.funcs->trace() call).
>>
> 
> Right, I can check this out.
> 

Hi Joel,

Sorry for the long delay in updating this thread.
But I just observed one weird behaviour in ftrace-ramoops when I was 
trying to use binary record instead of rendering text for event-ramoops.

Even though we set the ftrace-size in device tree for ramoops, the 
actual ftrace-ramoops record seems to have more records than specified size.
Is this expected or some bug?

Below is the ftrace-ramoops size passed in dtsi for db410c and we can 
see that the ftrace record is more.

# cat /sys/module/ramoops/parameters/ftrace_size
131072
#
# cat /sys/fs/pstore/ftrace-ramoops-0 | wc -c
560888
#
# cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:0 | wc -c
137758
#
# cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:1 | wc -c
140560
#
# cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:2 | wc -c
141174
#
# cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:3 | wc -c
141396
#

I don't see this in console or dmesg ramoops and also with the 
event-ramoops which I have posted since we don't use binary record, only 
ftrace-ramoops uses binary record to store trace data.

Also regarding the warning on "event_call->event.funcs->trace()" call,
I see it everytime without spinlock. Also we see output_printk using 
spinlock when making this call. I could not find a way to pass event 
buffer size and allocate in pstore. Steven can give some hints with this 
I guess.

Steven Rostedt gave some reviews about using raw_spinlocks for this call 
earlier in this thread. So is it right to not use spinlocks for trace 
events?

One difference I see in ftrace-ramoops and event-ramoops is that 
ftrace-ramoops  is not started on boot and event-ramoops logging can be 
enabled from boot (late initcall however).

Do let me know if you have any way to avoid this warning which is a race 
I think without spinlock.

Thanks,
Sai

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

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Steven Rostedt]

On Mon, 8 Oct 2018 19:46:15 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> Hi Joel,
> 
> Sorry for the long delay in updating this thread.
> But I just observed one weird behaviour in ftrace-ramoops when I was 
> trying to use binary record instead of rendering text for event-ramoops.
> 
> Even though we set the ftrace-size in device tree for ramoops, the 
> actual ftrace-ramoops record seems to have more records than specified size.
> Is this expected or some bug?

If ftrace-ramoops is using logic similar to the ftrace ring buffer,
then yes, it will be able to store more events than specified. The
ftrace ring buffer is broken up into pages, and everything is rounded
up to the nearest page (note, the data may be smaller than a page,
because each page also contains a header).

> 
> Below is the ftrace-ramoops size passed in dtsi for db410c and we can 
> see that the ftrace record is more.
> 
> # cat /sys/module/ramoops/parameters/ftrace_size
> 131072

I'm assuming this too is like the ftrace ring buffer, where the size is
per cpu (and why you do a search per cpu below).

> #
> # cat /sys/fs/pstore/ftrace-ramoops-0 | wc -c
> 560888
> #
> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:0 | wc -c
> 137758
> #
> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:1 | wc -c
> 140560
> #
> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:2 | wc -c
> 141174
> #
> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:3 | wc -c
> 141396
> #
> 

If you are using binary record, isn't this what you want? The
ftrace_size is the size of how much binary data is stored. When you
translate the binary into human text, the text should be bigger.

> I don't see this in console or dmesg ramoops and also with the 
> event-ramoops which I have posted since we don't use binary record, only 
> ftrace-ramoops uses binary record to store trace data.
> 
> Also regarding the warning on "event_call->event.funcs->trace()" call,
> I see it everytime without spinlock. Also we see output_printk using 
> spinlock when making this call. I could not find a way to pass event 
> buffer size and allocate in pstore. Steven can give some hints with this 
> I guess.
> 
> Steven Rostedt gave some reviews about using raw_spinlocks for this call 
> earlier in this thread. So is it right to not use spinlocks for trace 
> events?

Correct.

> 
> One difference I see in ftrace-ramoops and event-ramoops is that 
> ftrace-ramoops  is not started on boot and event-ramoops logging can be 
> enabled from boot (late initcall however).
> 
> Do let me know if you have any way to avoid this warning which is a race 
> I think without spinlock.

I guess I need to look at that code again too.

-- Steve

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Joel Fernandes]

On Mon, Oct 08, 2018 at 10:36:59AM -0400, Steven Rostedt wrote:
> On Mon, 8 Oct 2018 19:46:15 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
> > Hi Joel,
> > 
> > Sorry for the long delay in updating this thread.
> > But I just observed one weird behaviour in ftrace-ramoops when I was 
> > trying to use binary record instead of rendering text for event-ramoops.
> > 
> > Even though we set the ftrace-size in device tree for ramoops, the 
> > actual ftrace-ramoops record seems to have more records than specified size.
> > Is this expected or some bug?
> 
> If ftrace-ramoops is using logic similar to the ftrace ring buffer,
> then yes, it will be able to store more events than specified. The
> ftrace ring buffer is broken up into pages, and everything is rounded
> up to the nearest page (note, the data may be smaller than a page,
> because each page also contains a header).

In the pstore code, the pages are contiguous. The platform drivers for that
platform configure 'ftrace-size' which is in bytes. That is further divided
by the number of CPUs. The records from all the buffers are then merged at read time.

Each function trace record is of type:
struct pstore_ftrace_record {
        unsigned long ip;
        unsigned long parent_ip;
        u64 ts;
};

which should be 24 bytes.

But there is an ECC block (with ECC data and ECC header) added to each CPU in
this case of the backing store of the pstore being RAM (pstore backing stores
can be other media types too).

> > Below is the ftrace-ramoops size passed in dtsi for db410c and we can 
> > see that the ftrace record is more.
> > 
> > # cat /sys/module/ramoops/parameters/ftrace_size
> > 131072
> 
> I'm assuming this too is like the ftrace ring buffer, where the size is
> per cpu (and why you do a search per cpu below).
> 
> > #
> > # cat /sys/fs/pstore/ftrace-ramoops-0 | wc -c
> > 560888
> > #
> > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:0 | wc -c
> > 137758
> > #
> > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:1 | wc -c
> > 140560
> > #
> > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:2 | wc -c
> > 141174
> > #
> > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:3 | wc -c
> > 141396
> > #

That could be because you're counting text characters when you're counting.
You need to count the binary size.

> If you are using binary record, isn't this what you want? The
> ftrace_size is the size of how much binary data is stored. When you
> translate the binary into human text, the text should be bigger.
> 
> > I don't see this in console or dmesg ramoops and also with the 
> > event-ramoops which I have posted since we don't use binary record, only 
> > ftrace-ramoops uses binary record to store trace data.
> > 
> > Also regarding the warning on "event_call->event.funcs->trace()" call,
> > I see it everytime without spinlock. Also we see output_printk using 
> > spinlock when making this call. I could not find a way to pass event 
> > buffer size and allocate in pstore. Steven can give some hints with this 
> > I guess.

The spinlock warning you're talking about is this one correct?

[    1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 trace_raw_output_prep+0x18/0xa0
[    1.389416] Modules linked in:
which you reported here:
https://lkml.org/lkml/2018/9/22/319

This warning happens I think because you're trying to format the events while
the trace events are being generated. You said you got this warning when you
didn't use the spinlock. I believe the spinlocking prevents such races, but
if you didn't need to format the events into text into text in the first
place, then you wouldn't need such locking at all. 

I believe ftrace doesn't have such issues because such locking is taken care
off when the trace events are formatted from the trace buffer and displayed,
but I could be wrong about that.. I'll let Steven provide more inputs about
how this warning can occur.

As a suggestion, please always provide references to the warnings you're
referring to, such as previous LKML posts or atleast the warning message so
folks know which warning you're talking about.

thanks,

 - Joel

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Sai Prakash Ranjan]

On 10/9/2018 4:10 AM, Joel Fernandes wrote:
> On Mon, Oct 08, 2018 at 10:36:59AM -0400, Steven Rostedt wrote:
>> On Mon, 8 Oct 2018 19:46:15 +0530
>> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
>>
>>> Hi Joel,
>>>
>>> Sorry for the long delay in updating this thread.
>>> But I just observed one weird behaviour in ftrace-ramoops when I was
>>> trying to use binary record instead of rendering text for event-ramoops.
>>>
>>> Even though we set the ftrace-size in device tree for ramoops, the
>>> actual ftrace-ramoops record seems to have more records than specified size.
>>> Is this expected or some bug?
>>
>> If ftrace-ramoops is using logic similar to the ftrace ring buffer,
>> then yes, it will be able to store more events than specified. The
>> ftrace ring buffer is broken up into pages, and everything is rounded
>> up to the nearest page (note, the data may be smaller than a page,
>> because each page also contains a header).
> 
> In the pstore code, the pages are contiguous. The platform drivers for that
> platform configure 'ftrace-size' which is in bytes. That is further divided
> by the number of CPUs. The records from all the buffers are then merged at read time.
> 
> Each function trace record is of type:
> struct pstore_ftrace_record {
>          unsigned long ip;
>          unsigned long parent_ip;
>          u64 ts;
> };
> 
> which should be 24 bytes.
> 
> But there is an ECC block (with ECC data and ECC header) added to each CPU in
> this case of the backing store of the pstore being RAM (pstore backing stores
> can be other media types too).
> 

Thanks for this info.

>>> Below is the ftrace-ramoops size passed in dtsi for db410c and we can
>>> see that the ftrace record is more.
>>>
>>> # cat /sys/module/ramoops/parameters/ftrace_size
>>> 131072
>>
>> I'm assuming this too is like the ftrace ring buffer, where the size is
>> per cpu (and why you do a search per cpu below).
>>
>>> #
>>> # cat /sys/fs/pstore/ftrace-ramoops-0 | wc -c
>>> 560888
>>> #
>>> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:0 | wc -c
>>> 137758
>>> #
>>> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:1 | wc -c
>>> 140560
>>> #
>>> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:2 | wc -c
>>> 141174
>>> #
>>> # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:3 | wc -c
>>> 141396
>>> #
> 
> That could be because you're counting text characters when you're counting.
> You need to count the binary size.
> 

Right thanks.

>> If you are using binary record, isn't this what you want? The
>> ftrace_size is the size of how much binary data is stored. When you
>> translate the binary into human text, the text should be bigger.
>>
>>> I don't see this in console or dmesg ramoops and also with the
>>> event-ramoops which I have posted since we don't use binary record, only
>>> ftrace-ramoops uses binary record to store trace data.
>>>
>>> Also regarding the warning on "event_call->event.funcs->trace()" call,
>>> I see it everytime without spinlock. Also we see output_printk using
>>> spinlock when making this call. I could not find a way to pass event
>>> buffer size and allocate in pstore. Steven can give some hints with this
>>> I guess.
> 
> The spinlock warning you're talking about is this one correct?
> 
> [    1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 trace_raw_output_prep+0x18/0xa0
> [    1.389416] Modules linked in:
> which you reported here:
> https://lkml.org/lkml/2018/9/22/319
> 
> This warning happens I think because you're trying to format the events while
> the trace events are being generated. You said you got this warning when you
> didn't use the spinlock. I believe the spinlocking prevents such races, but
> if you didn't need to format the events into text into text in the first
> place, then you wouldn't need such locking at all.
> 
> I believe ftrace doesn't have such issues because such locking is taken care
> off when the trace events are formatted from the trace buffer and displayed,
> but I could be wrong about that.. I'll let Steven provide more inputs about
> how this warning can occur.
Yes Steven would have more insight on this warning.

> 
> As a suggestion, please always provide references to the warnings you're
> referring to, such as previous LKML posts or atleast the warning message so
> folks know which warning you're talking about.
> 

Yes sure.

Thanks,
Sai

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

Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Steven Rostedt]

On Tue, 9 Oct 2018 23:52:14 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> >>> Also regarding the warning on "event_call->event.funcs->trace()" call,
> >>> I see it everytime without spinlock. Also we see output_printk using
> >>> spinlock when making this call. I could not find a way to pass event
> >>> buffer size and allocate in pstore. Steven can give some hints with this
> >>> I guess.  
> > 
> > The spinlock warning you're talking about is this one correct?
> > 
> > [    1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 trace_raw_output_prep+0x18/0xa0
> > [    1.389416] Modules linked in:
> > which you reported here:
> > https://lkml.org/lkml/2018/9/22/319
> > 
> > This warning happens I think because you're trying to format the events while
> > the trace events are being generated. You said you got this warning when you
> > didn't use the spinlock. I believe the spinlocking prevents such races, but
> > if you didn't need to format the events into text into text in the first
> > place, then you wouldn't need such locking at all.
> > 
> > I believe ftrace doesn't have such issues because such locking is taken care
> > off when the trace events are formatted from the trace buffer and displayed,
> > but I could be wrong about that.. I'll let Steven provide more inputs about
> > how this warning can occur.  
> Yes Steven would have more insight on this warning.

Correct. Formatting should not be done at the location of recording
(it's way too much overhead). Even trace_printk() doesn't format string
at the execution path, but does so at the presentation path (reading
the buffer, via reads of the trace file, or in trace-cmd post
processing of the trace.dat file).

trace_printk() uses vbin_printf() which doesn't do printf()
conversions, but instead only saves the format string and the raw
values into the buffer. Then in uses bstr_printf() that takes the
format string and raw values to produce the "printf()" output you know
and love.

-- Steve

[PATCH 4/6] arm64/io: Add tracepoint for register accesses

[Sai Prakash Ranjan]

Generic IO read/write i.e., __raw_{read,write}{b,l,w,q} are
typically used to read/write from/to memory mapped registers,
which can cause hangs or some undefined behaviour if access
unclocked. Tracing these register accesses can be very helpful
to debug such issues during initial development stages.
This can be used later for tracing arm IO register accesses.

Sample output format of register access trace is below:

  io_write: type=writel cpu=3 ts:1424714326 data=0xffff00000d1065a4 caller=qcom_smsm_probe+0x52c/0x678
  io_write: type=writel cpu=3 ts:1424962659 data=0xffff00000d106608 caller=qcom_smsm_probe+0x52c/0x678

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 arch/arm64/kernel/io.c         | 22 +++++++++++
 include/asm-generic/io-trace.h | 70 ++++++++++++++++++++++++++++++++++
 2 files changed, 92 insertions(+)
 create mode 100644 include/asm-generic/io-trace.h

diff --git a/arch/arm64/kernel/io.c b/arch/arm64/kernel/io.c
index 79b17384effa..a9db07f66477 100644
--- a/arch/arm64/kernel/io.c
+++ b/arch/arm64/kernel/io.c
@@ -19,6 +19,10 @@
 #include <linux/export.h>
 #include <linux/types.h>
 #include <linux/io.h>
+#include <linux/sched/clock.h>
+
+#define CREATE_TRACE_POINTS
+#include <asm-generic/io-trace.h>
 
 /*
  * Copy data from IO memory space to "real" memory space.
@@ -106,3 +110,21 @@ void __memset_io(volatile void __iomem *dst, int c, size_t count)
 	}
 }
 EXPORT_SYMBOL(__memset_io);
+
+#if defined(CONFIG_TRACING_EVENTS_IO)
+void do_trace_io_write(const char *type, void *addr)
+{
+	trace_io_write(type, raw_smp_processor_id(), sched_clock(), addr,
+		       _RET_IP_);
+}
+EXPORT_SYMBOL(do_trace_io_write);
+EXPORT_TRACEPOINT_SYMBOL(io_write);
+
+void do_trace_io_read(const char *type, void *addr)
+{
+	trace_io_read(type, raw_smp_processor_id(), sched_clock(), addr,
+		      _RET_IP_);
+}
+EXPORT_SYMBOL(do_trace_io_read);
+EXPORT_TRACEPOINT_SYMBOL(io_read);
+#endif
diff --git a/include/asm-generic/io-trace.h b/include/asm-generic/io-trace.h
new file mode 100644
index 000000000000..e57b52d8976a
--- /dev/null
+++ b/include/asm-generic/io-trace.h
@@ -0,0 +1,70 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM io
+
+#if !defined(CONFIG_TRACING_EVENTS_IO)
+#define NOTRACE
+#endif
+
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE io-trace
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH asm-generic
+
+#if !defined(_TRACE_IO_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IO_H
+
+#include <linux/tracepoint.h>
+
+/*
+ * Tracepoint for generic IO read/write, i.e., __raw_{read,write}{b,l,w,q}()
+ */
+DECLARE_EVENT_CLASS(io_trace_class,
+
+	TP_PROTO(const char *type, int cpu, u64 ts, void *addr,
+		 unsigned long ret_ip),
+
+	TP_ARGS(type, cpu, ts, addr, ret_ip),
+
+	TP_STRUCT__entry(
+		__string(	type,		type	)
+		__field(	int,		cpu	)
+		__field(	u64,		ts	)
+		__field(	void *,		addr	)
+		__field(	unsigned long,	ret_ip	)
+	),
+
+	TP_fast_assign(
+		__assign_str(type, type);
+		__entry->cpu	= cpu;
+		__entry->ts	= ts;
+		__entry->addr	= addr;
+		__entry->ret_ip	= ret_ip;
+	),
+
+	TP_printk("type=%s cpu=%d ts:%llu data=0x%lx caller=%pS",
+		  __get_str(type), __entry->cpu, __entry->ts,
+		  (unsigned long)__entry->addr, (void *)__entry->ret_ip)
+);
+
+DEFINE_EVENT(io_trace_class, io_read,
+
+	TP_PROTO(const char *type, int cpu, u64 ts, void *addr,
+		 unsigned long ret_ip),
+
+	TP_ARGS(type, cpu, ts, addr, ret_ip)
+);
+
+DEFINE_EVENT(io_trace_class, io_write,
+
+	TP_PROTO(const char *type, int cpu, u64 ts, void *addr,
+		 unsigned long ret_ip),
+
+	TP_ARGS(type, cpu, ts, addr, ret_ip)
+);
+
+#endif /* _TRACE_IO_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

[PATCH 5/6] arm64/io: Add header for instrumentation of io operations

[Sai Prakash Ranjan]

The new asm-generic/io-instrumented.h will keep arch code
clean and separate from instrumented version which traces
io register accesses. This instrumented header can later
be included in arm as well for tracing io register accesses.

Suggested-by: Will Deacon <will.deacon@arm.com>
Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 arch/arm64/include/asm/io.h           | 25 ++++++---------
 include/asm-generic/io-instrumented.h | 45 +++++++++++++++++++++++++++
 2 files changed, 54 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..768a6a8c5778 100644
--- a/arch/arm64/include/asm/io.h
+++ b/arch/arm64/include/asm/io.h
@@ -36,32 +36,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 +66,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 +77,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 +87,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 +185,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..7b050e2487ed
--- /dev/null
+++ b/include/asm-generic/io-instrumented.h
@@ -0,0 +1,45 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
+#define _ASM_GENERIC_IO_INSTRUMENTED_H
+
+#if defined(CONFIG_TRACING_EVENTS_IO)
+#include <linux/tracepoint-defs.h>
+
+extern struct tracepoint __tracepoint_io_write;
+extern struct tracepoint __tracepoint_io_read;
+#define io_tracepoint_active(t) static_key_false(&(t).key)
+extern void do_trace_io_write(const char *type, void *addr);
+extern void do_trace_io_read(const char *type, void *addr);
+#else
+#define io_tracepoint_active(t) false
+static inline void do_trace_io_write(const char *type, void *addr) {}
+static inline void do_trace_io_read(const char *type, void *addr) {}
+#endif /* CONFIG_TRACING_EVENTS_IO */
+
+#define __raw_write(v, a, _l)	({						\
+	volatile void __iomem *_a = (a);					\
+	if (io_tracepoint_active(__tracepoint_io_write))			\
+		do_trace_io_write(__stringify(write##_l), (void __force *)(_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 (io_tracepoint_active(__tracepoint_io_read))				\
+		do_trace_io_read(__stringify(read##_l), (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 /* _ASM_GENERIC_IO_INSTRUMENTED_H */
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [PATCH 5/6] arm64/io: Add header for instrumentation of io operations

[Steven Rostedt]

On Sun,  9 Sep 2018 01:57:06 +0530
Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:

> The new asm-generic/io-instrumented.h will keep arch code
> clean and separate from instrumented version which traces
> io register accesses. This instrumented header can later
> be included in arm as well for tracing io register accesses.
> 

Looks good to me.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

> Suggested-by: Will Deacon <will.deacon@arm.com>
> Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
> ---
>  arch/arm64/include/asm/io.h           | 25 ++++++---------
>  include/asm-generic/io-instrumented.h | 45 +++++++++++++++++++++++++++
>  2 files changed, 54 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..768a6a8c5778 100644
> --- a/arch/arm64/include/asm/io.h
> +++ b/arch/arm64/include/asm/io.h
> @@ -36,32 +36,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 +66,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 +77,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 +87,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 +185,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..7b050e2487ed
> --- /dev/null
> +++ b/include/asm-generic/io-instrumented.h
> @@ -0,0 +1,45 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
> +#define _ASM_GENERIC_IO_INSTRUMENTED_H
> +
> +#if defined(CONFIG_TRACING_EVENTS_IO)
> +#include <linux/tracepoint-defs.h>
> +
> +extern struct tracepoint __tracepoint_io_write;
> +extern struct tracepoint __tracepoint_io_read;
> +#define io_tracepoint_active(t) static_key_false(&(t).key)
> +extern void do_trace_io_write(const char *type, void *addr);
> +extern void do_trace_io_read(const char *type, void *addr);
> +#else
> +#define io_tracepoint_active(t) false
> +static inline void do_trace_io_write(const char *type, void *addr) {}
> +static inline void do_trace_io_read(const char *type, void *addr) {}
> +#endif /* CONFIG_TRACING_EVENTS_IO */
> +
> +#define __raw_write(v, a, _l)	({						\
> +	volatile void __iomem *_a = (a);					\
> +	if (io_tracepoint_active(__tracepoint_io_write))			\
> +		do_trace_io_write(__stringify(write##_l), (void __force *)(_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 (io_tracepoint_active(__tracepoint_io_read))				\
> +		do_trace_io_read(__stringify(read##_l), (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 /* _ASM_GENERIC_IO_INSTRUMENTED_H */

Re: [PATCH 5/6] arm64/io: Add header for instrumentation of io operations

[Sai Prakash Ranjan]

On 9/18/2018 5:09 AM, Steven Rostedt wrote:
> On Sun,  9 Sep 2018 01:57:06 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
>> The new asm-generic/io-instrumented.h will keep arch code
>> clean and separate from instrumented version which traces
>> io register accesses. This instrumented header can later
>> be included in arm as well for tracing io register accesses.
>>
> 
> Looks good to me.
> 
> Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> 
> -- Steve

Thanks for the ack Steve.

@Will/Mark/Robin Let me know if you have any review comments, thanks.

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

Re: [PATCH 5/6] arm64/io: Add header for instrumentation of io operations

[Will Deacon]

On Tue, Sep 18, 2018 at 12:40:57PM +0530, Sai Prakash Ranjan wrote:
> On 9/18/2018 5:09 AM, Steven Rostedt wrote:
> >On Sun,  9 Sep 2018 01:57:06 +0530
> >Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> >
> >>The new asm-generic/io-instrumented.h will keep arch code
> >>clean and separate from instrumented version which traces
> >>io register accesses. This instrumented header can later
> >>be included in arm as well for tracing io register accesses.
> >>
> >
> >Looks good to me.
> >
> >Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> >
> >-- Steve
> 
> Thanks for the ack Steve.
> 
> @Will/Mark/Robin Let me know if you have any review comments, thanks.

As I said before, the arm64 bits looks fine to me. I just don't really want
to Ack the thing because the patch also contains the asm-generic changes.

Will

Re: [PATCH 5/6] arm64/io: Add header for instrumentation of io operations

[Sai Prakash Ranjan]

On 9/18/2018 5:17 PM, Will Deacon wrote:
> On Tue, Sep 18, 2018 at 12:40:57PM +0530, Sai Prakash Ranjan wrote:
>> On 9/18/2018 5:09 AM, Steven Rostedt wrote:
>>> On Sun,  9 Sep 2018 01:57:06 +0530
>>> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>>> The new asm-generic/io-instrumented.h will keep arch code
>>>> clean and separate from instrumented version which traces
>>>> io register accesses. This instrumented header can later
>>>> be included in arm as well for tracing io register accesses.
>>>>
>>>
>>> Looks good to me.
>>>
>>> Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
>>>
>>> -- Steve
>>
>> Thanks for the ack Steve.
>>
>> @Will/Mark/Robin Let me know if you have any review comments, thanks.
> 
> As I said before, the arm64 bits looks fine to me. I just don't really want
> to Ack the thing because the patch also contains the asm-generic changes.
> 
> Will
> 

Ok thank you. Is there anyone else whom I should add for asm-generic?

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

[PATCH 6/6] dynamic_debug: Add 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 IO 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 for tracing register accesses in drivers/soc/qcom/*
and the pstore output is given below:

  # dyndbg="file drivers/soc/qcom/* +e" trace_event=io tp_pstore
  # reboot -f
  # mount -t pstore pstore /sys/fs/pstore
  # cat /sys/fs/pstore/event-ramoops-0
    io_write: type=writel cpu=1 ts:1423596253 data=0xffff00000d2065a4 caller=qcom_smsm_probe+0x524/0x670
    io_write: type=writel cpu=1 ts:1423945889 data=0xffff00000d206608 caller=qcom_smsm_probe+0x524/0x670

Note: Tracing is activated only when flag is enabled either
through command line or through dynamic debug control file.

Signed-off-by: Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>
---
 include/asm-generic/io-instrumented.h | 28 +++++++++++++++++++++++++--
 include/linux/dynamic_debug.h         |  1 +
 lib/dynamic_debug.c                   |  1 +
 3 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/include/asm-generic/io-instrumented.h b/include/asm-generic/io-instrumented.h
index 7b050e2487ed..023f28571ea3 100644
--- a/include/asm-generic/io-instrumented.h
+++ b/include/asm-generic/io-instrumented.h
@@ -2,6 +2,8 @@
 #ifndef _ASM_GENERIC_IO_INSTRUMENTED_H
 #define _ASM_GENERIC_IO_INSTRUMENTED_H
 
+#include <linux/dynamic_debug.h>
+
 #if defined(CONFIG_TRACING_EVENTS_IO)
 #include <linux/tracepoint-defs.h>
 
@@ -19,7 +21,7 @@ static inline void do_trace_io_read(const char *type, void *addr) {}
 #define __raw_write(v, a, _l)	({						\
 	volatile void __iomem *_a = (a);					\
 	if (io_tracepoint_active(__tracepoint_io_write))			\
-		do_trace_io_write(__stringify(write##_l), (void __force *)(_a));\
+		dynamic_io_write(__stringify(write##_l), (void __force *)(_a));	\
 	arch_raw_write##_l((v), _a);						\
 	})
 
@@ -32,7 +34,7 @@ static inline void do_trace_io_read(const char *type, void *addr) {}
 	_t __a;									\
 	const volatile void __iomem *_a = (a);					\
 	if (io_tracepoint_active(__tracepoint_io_read))				\
-		do_trace_io_read(__stringify(read##_l), (void __force *)(_a));	\
+		dynamic_io_read(__stringify(read##_l), (void __force *)(_a));	\
 	__a = arch_raw_read##_l(_a);						\
 	__a;									\
 	})
@@ -42,4 +44,26 @@ static inline void do_trace_io_read(const char *type, void *addr) {}
 #define __raw_readl(a)	__raw_read((a), l, u32)
 #define __raw_readq(a)	__raw_read((a), q, u64)
 
+#if defined(CONFIG_DYNAMIC_DEBUG) && defined(CONFIG_TRACING_EVENTS_IO)
+#define dynamic_io_write(type, addr)					\
+do {									\
+	DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, type);		\
+	if (unlikely(descriptor.flags & _DPRINTK_FLAGS_EVENT))		\
+		do_trace_io_write(type, addr);				\
+} while (0)
+
+#define dynamic_io_read(type, addr)					\
+do {									\
+	DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, type);		\
+	if (unlikely(descriptor.flags & _DPRINTK_FLAGS_EVENT))		\
+		do_trace_io_read(type, addr);				\
+} while (0)
+#elif defined(CONFIG_TRACING_EVENTS_IO)
+#define dynamic_io_write(type, addr)	do_trace_io_write(type, addr)
+#define dynamic_io_read(type, addr)	do_trace_io_read(type, addr)
+#else
+#define dynamic_io_write(type, addr)
+#define dynamic_io_read(type, addr)
+#endif /* CONFIG_DYNAMIC_DEBUG && CONFIG_TRACING_EVENTS_IO */
+
 #endif /* _ASM_GENERIC_IO_INSTRUMENTED_H */
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 2fd8006153c3..14e595c51002 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)
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c7c96bc7654a..694957a8ae54 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -78,6 +78,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' },
-- 
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Will Deacon]

Hello,

On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
> This patch series adds Event tracing support to pstore and is continuation
> to the RFC patch introduced to add a new tracing facility for register
> accesses called Register Trace Buffer(RTB). Since we decided to not introduce
> a separate framework to trace register accesses and use existing framework
> like tracepoints, I have moved from RFC. Details of the RFC in link below:
> 
> Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/

The arm64 backend bits look fine to be, but they're mixed up with core
changes that I haven't looked at closely.

Will

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Sai Prakash Ranjan]

On 9/11/2018 8:41 PM, Will Deacon wrote:
> Hello,
> 
> On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
>> This patch series adds Event tracing support to pstore and is continuation
>> to the RFC patch introduced to add a new tracing facility for register
>> accesses called Register Trace Buffer(RTB). Since we decided to not introduce
>> a separate framework to trace register accesses and use existing framework
>> like tracepoints, I have moved from RFC. Details of the RFC in link below:
>>
>> Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
> 
> The arm64 backend bits look fine to be, but they're mixed up with core
> changes that I haven't looked at closely.
> 
Hi Will,

Thanks for the review. Let me know if you have any suggestions or points 
regarding this patch, I will be happy to incorporate it.

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Joel Fernandes]

On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
> Hi,
> 
> This patch series adds Event tracing support to pstore and is continuation
> to the RFC patch introduced to add a new tracing facility for register
> accesses called Register Trace Buffer(RTB). Since we decided to not introduce
> a separate framework to trace register accesses and use existing framework
> like tracepoints, I have moved from RFC. Details of the RFC in link below:
> 
> Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
> 
> MSR tracing example given by Steven was helpful in using tracepoints for
> register accesses instead of using separate trace. But just having these
> IO traces would not help much unless we could have them in some persistent
> ram buffer for debugging 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. By analyzing the last few entries of this buffer,
> we could identify the register access which is causing the issue.

Hi Sai,

I wanted to see if I could make some time to get your patches working. We are
hitting usecases that need something like this as well. Basically devices
hanging and then the ramdump does not tell us much, so in this case pstore
events can be really helpful. This usecase came up last year as well.

Anyway while I was going through your patches, I cleaned up some pstore code
as well and I have 3 more patches on top of yours for this clean up. I prefer
we submit the patches together and sync our work together so that there is
least conflict.

Here's my latest tree:
https://github.com/joelagnel/linux-kernel/commits/pstore-events
(note that I have only build tested the patches since I just wrote them and
its quite late in the night here ;-))

thanks,

- Joel

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Sai Prakash Ranjan]

On 10/20/2018 10:55 AM, Joel Fernandes wrote:
> On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
>> Hi,
>>
>> This patch series adds Event tracing support to pstore and is continuation
>> to the RFC patch introduced to add a new tracing facility for register
>> accesses called Register Trace Buffer(RTB). Since we decided to not introduce
>> a separate framework to trace register accesses and use existing framework
>> like tracepoints, I have moved from RFC. Details of the RFC in link below:
>>
>> Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
>>
>> MSR tracing example given by Steven was helpful in using tracepoints for
>> register accesses instead of using separate trace. But just having these
>> IO traces would not help much unless we could have them in some persistent
>> ram buffer for debugging 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. By analyzing the last few entries of this buffer,
>> we could identify the register access which is causing the issue.
> 
> Hi Sai,
> 
> I wanted to see if I could make some time to get your patches working. We are
> hitting usecases that need something like this as well. Basically devices
> hanging and then the ramdump does not tell us much, so in this case pstore
> events can be really helpful. This usecase came up last year as well.
> 
> Anyway while I was going through your patches, I cleaned up some pstore code
> as well and I have 3 more patches on top of yours for this clean up. I prefer
> we submit the patches together and sync our work together so that there is
> least conflict.
> 
> Here's my latest tree:
> https://github.com/joelagnel/linux-kernel/commits/pstore-events
> (note that I have only build tested the patches since I just wrote them and
> its quite late in the night here ;-))
> 

Hi Joel,

Thanks for looking into this. Sure, I will be happy to sync up with you 
on this. I can test your additional patches on top of my pstore patches. 
BTW, I'm still stuck at copying binary record into pstore and then 
extract it during read time. Seems like I'm missing something.

Thanks,
Sai

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

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Joel Fernandes]

On Sat, Oct 20, 2018 at 12:02:37PM +0530, Sai Prakash Ranjan wrote:
> On 10/20/2018 10:55 AM, Joel Fernandes wrote:
> > On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
> > > Hi,
> > > 
> > > This patch series adds Event tracing support to pstore and is continuation
> > > to the RFC patch introduced to add a new tracing facility for register
> > > accesses called Register Trace Buffer(RTB). Since we decided to not introduce
> > > a separate framework to trace register accesses and use existing framework
> > > like tracepoints, I have moved from RFC. Details of the RFC in link below:
> > > 
> > > Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
> > > 
> > > MSR tracing example given by Steven was helpful in using tracepoints for
> > > register accesses instead of using separate trace. But just having these
> > > IO traces would not help much unless we could have them in some persistent
> > > ram buffer for debugging 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. By analyzing the last few entries of this buffer,
> > > we could identify the register access which is causing the issue.
> > 
> > Hi Sai,
> > 
> > I wanted to see if I could make some time to get your patches working. We are
> > hitting usecases that need something like this as well. Basically devices
> > hanging and then the ramdump does not tell us much, so in this case pstore
> > events can be really helpful. This usecase came up last year as well.
> > 
> > Anyway while I was going through your patches, I cleaned up some pstore code
> > as well and I have 3 more patches on top of yours for this clean up. I prefer
> > we submit the patches together and sync our work together so that there is
> > least conflict.
> > 
> > Here's my latest tree:
> > https://github.com/joelagnel/linux-kernel/commits/pstore-events
> > (note that I have only build tested the patches since I just wrote them and
> > its quite late in the night here ;-))
> > 
> 
> Hi Joel,
> 
> Thanks for looking into this. Sure, I will be happy to sync up with you on

Thanks. And added a fourth patch in the tree too.

> this. I can test your additional patches on top of my pstore patches. BTW,
> I'm still stuck at copying binary record into pstore and then extract it
> during read time. Seems like I'm missing something.

Sure, push your latest somewhere and let me know. I'll try to get you unstuck.

thanks,

 - Joel

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Sai Prakash Ranjan]

On 10/20/2018 9:57 PM, Joel Fernandes wrote:
> On Sat, Oct 20, 2018 at 12:02:37PM +0530, Sai Prakash Ranjan wrote:
>> On 10/20/2018 10:55 AM, Joel Fernandes wrote:
>>> On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
>>>> Hi,
>>>>
>>>> This patch series adds Event tracing support to pstore and is continuation
>>>> to the RFC patch introduced to add a new tracing facility for register
>>>> accesses called Register Trace Buffer(RTB). Since we decided to not introduce
>>>> a separate framework to trace register accesses and use existing framework
>>>> like tracepoints, I have moved from RFC. Details of the RFC in link below:
>>>>
>>>> Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
>>>>
>>>> MSR tracing example given by Steven was helpful in using tracepoints for
>>>> register accesses instead of using separate trace. But just having these
>>>> IO traces would not help much unless we could have them in some persistent
>>>> ram buffer for debugging 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. By analyzing the last few entries of this buffer,
>>>> we could identify the register access which is causing the issue.
>>>
>>> Hi Sai,
>>>
>>> I wanted to see if I could make some time to get your patches working. We are
>>> hitting usecases that need something like this as well. Basically devices
>>> hanging and then the ramdump does not tell us much, so in this case pstore
>>> events can be really helpful. This usecase came up last year as well.
>>>
>>> Anyway while I was going through your patches, I cleaned up some pstore code
>>> as well and I have 3 more patches on top of yours for this clean up. I prefer
>>> we submit the patches together and sync our work together so that there is
>>> least conflict.
>>>
>>> Here's my latest tree:
>>> https://github.com/joelagnel/linux-kernel/commits/pstore-events
>>> (note that I have only build tested the patches since I just wrote them and
>>> its quite late in the night here ;-))
>>>
>>
>> Hi Joel,
>>
>> Thanks for looking into this. Sure, I will be happy to sync up with you on
> 
> Thanks. And added a fourth patch in the tree too.
> 
>> this. I can test your additional patches on top of my pstore patches. BTW,
>> I'm still stuck at copying binary record into pstore and then extract it
>> during read time. Seems like I'm missing something.
> 
> Sure, push your latest somewhere and let me know. I'll try to get you unstuck.
> 

Thanks Joel, I will push my changes and let you know in some time.

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

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Sai Prakash Ranjan]

On 10/21/2018 9:16 AM, Sai Prakash Ranjan wrote:
> On 10/20/2018 9:57 PM, Joel Fernandes wrote:
>> On Sat, Oct 20, 2018 at 12:02:37PM +0530, Sai Prakash Ranjan wrote:
>>> On 10/20/2018 10:55 AM, Joel Fernandes wrote:
>>>> On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
>>>>> Hi,
>>>>>
>>>>> This patch series adds Event tracing support to pstore and is 
>>>>> continuation
>>>>> to the RFC patch introduced to add a new tracing facility for register
>>>>> accesses called Register Trace Buffer(RTB). Since we decided to not 
>>>>> introduce
>>>>> a separate framework to trace register accesses and use existing 
>>>>> framework
>>>>> like tracepoints, I have moved from RFC. Details of the RFC in link 
>>>>> below:
>>>>>
>>>>> Link: 
>>>>> https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/ 
>>>>>
>>>>>
>>>>> MSR tracing example given by Steven was helpful in using 
>>>>> tracepoints for
>>>>> register accesses instead of using separate trace. But just having 
>>>>> these
>>>>> IO traces would not help much unless we could have them in some 
>>>>> persistent
>>>>> ram buffer for debugging 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. By analyzing the last few entries of 
>>>>> this buffer,
>>>>> we could identify the register access which is causing the issue.
>>>>
>>>> Hi Sai,
>>>>
>>>> I wanted to see if I could make some time to get your patches 
>>>> working. We are
>>>> hitting usecases that need something like this as well. Basically 
>>>> devices
>>>> hanging and then the ramdump does not tell us much, so in this case 
>>>> pstore
>>>> events can be really helpful. This usecase came up last year as well.
>>>>
>>>> Anyway while I was going through your patches, I cleaned up some 
>>>> pstore code
>>>> as well and I have 3 more patches on top of yours for this clean up. 
>>>> I prefer
>>>> we submit the patches together and sync our work together so that 
>>>> there is
>>>> least conflict.
>>>>
>>>> Here's my latest tree:
>>>> https://github.com/joelagnel/linux-kernel/commits/pstore-events
>>>> (note that I have only build tested the patches since I just wrote 
>>>> them and
>>>> its quite late in the night here ;-))
>>>>
>>>
>>> Hi Joel,
>>>
>>> Thanks for looking into this. Sure, I will be happy to sync up with 
>>> you on
>>
>> Thanks. And added a fourth patch in the tree too.
>>
>>> this. I can test your additional patches on top of my pstore patches. 
>>> BTW,
>>> I'm still stuck at copying binary record into pstore and then extract it
>>> during read time. Seems like I'm missing something.
>>
>> Sure, push your latest somewhere and let me know. I'll try to get you 
>> unstuck.
>>
> 
> Thanks Joel, I will push my changes and let you know in some time.
> 

Hi Joel,

Here's my tree:
https://github.com/saiprakash-ranjan/linux/commits/pstore-events

I have one patch extra on top of your patches. Nothing much on binary 
record storage in this patch, only removed kmalloc in pstore event call 
to avoid loop.

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

Re: [PATCH 0/6] Tracing register accesses with pstore and dynamic debug

[Joel Fernandes]

On Sun, Oct 21, 2018 at 09:16:59AM +0530, Sai Prakash Ranjan wrote:
> On 10/20/2018 9:57 PM, Joel Fernandes wrote:
> > On Sat, Oct 20, 2018 at 12:02:37PM +0530, Sai Prakash Ranjan wrote:
> > > On 10/20/2018 10:55 AM, Joel Fernandes wrote:
> > > > On Sun, Sep 09, 2018 at 01:57:01AM +0530, Sai Prakash Ranjan wrote:
> > > > > Hi,
> > > > > 
> > > > > This patch series adds Event tracing support to pstore and is continuation
> > > > > to the RFC patch introduced to add a new tracing facility for register
> > > > > accesses called Register Trace Buffer(RTB). Since we decided to not introduce
> > > > > a separate framework to trace register accesses and use existing framework
> > > > > like tracepoints, I have moved from RFC. Details of the RFC in link below:
> > > > > 
> > > > > Link: https://lore.kernel.org/lkml/cover.1535119710.git.saiprakash.ranjan@codeaurora.org/
> > > > > 
> > > > > MSR tracing example given by Steven was helpful in using tracepoints for
> > > > > register accesses instead of using separate trace. But just having these
> > > > > IO traces would not help much unless we could have them in some persistent
> > > > > ram buffer for debugging 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. By analyzing the last few entries of this buffer,
> > > > > we could identify the register access which is causing the issue.
> > > > 
> > > > Hi Sai,
> > > > 
> > > > I wanted to see if I could make some time to get your patches working. We are
> > > > hitting usecases that need something like this as well. Basically devices
> > > > hanging and then the ramdump does not tell us much, so in this case pstore
> > > > events can be really helpful. This usecase came up last year as well.
> > > > 
> > > > Anyway while I was going through your patches, I cleaned up some pstore code
> > > > as well and I have 3 more patches on top of yours for this clean up. I prefer
> > > > we submit the patches together and sync our work together so that there is
> > > > least conflict.
> > > > 
> > > > Here's my latest tree:
> > > > https://github.com/joelagnel/linux-kernel/commits/pstore-events
> > > > (note that I have only build tested the patches since I just wrote them and
> > > > its quite late in the night here ;-))
> > > > 
> > > 
> > > Hi Joel,
> > > 
> > > Thanks for looking into this. Sure, I will be happy to sync up with you on
> > 
> > Thanks. And added a fourth patch in the tree too.


While at it, I was thinking about the problem we are trying to solve in
another way. If ftrace itself can use pages from the persistent ram store,
instead of the kernel's buddy allocator, then the ftrace ring buffer itself
could persist across a system reboot.

The clear advantage of that for Sai's pstore events work is, not having to
duplicate a lot of the ring buffer code and stuff into pstore (for the pstore
events for example, I wanted time stamps as well and ftrace's ring buffer has
some nice time management code to deal with time deltas). We already have
other ring buffers maintained in other parts of the kernel for tracing right?
So I'm a bit averse to duplicating that into pstore as well for tracing. The
other advantage of persisting the ftrace ring buffer would also mean data
from other tracers such as function-graph tracer and irqsoff tracers would
also persist and then we can also probably get rid of ftrace-in-pstore stuff
which is kind of incomplete anyway since it does not have time stamps for
recorded functions.

Steven and Kees: what do you think, is persisting ftrace ring buffer across
reboots a worthwhile idea? Any thoughts on how feasible something like that
could be, code wise? Off the top, I think the ring buffer state that ftrace
needs other than the trace data itself will also have to be persisted.

thanks,

 - Joel