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

From: Sai Prakash Ranjan
Date: Sun Sep 16 2018 - 03:20:03 EST

Next message: Jiri Slaby: "Re: çå: Re: çå: Re: [PATCH] tty: max3100: Fix oops while 'cat/proc/tty/driver/ttyMAX'"
Previous message: Pavel Machek: "Re: v4.19-rc3 on thinkpad x220: kernel BUG at kernel/dma/swiotlb.c:521 when enabling radios"
Next in thread: Kees Cook: "Re: [PATCH 2/6] pstore: Add event tracing support"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Next message: Jiri Slaby: "Re: çå: Re: çå: Re: [PATCH] tty: max3100: Fix oops while 'cat/proc/tty/driver/ttyMAX'"
Previous message: Pavel Machek: "Re: v4.19-rc3 on thinkpad x220: kernel BUG at kernel/dma/swiotlb.c:521 when enabling radios"
Next in thread: Kees Cook: "Re: [PATCH 2/6] pstore: Add event tracing support"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]