2015-06-16 07:06:42

by Chunyan Zhang

[permalink] [raw]
Subject: [RFC PATCH v2 0/3] Integration of trace events with System Trace IP blocks

IP blocks allowing a variety of trace sources to log debugging
information to a pre-defined area have been introduced on a couple of
architecture [1][2]. These system trace blocks (also known as STM)
typically follow the MIPI STPv2 protocol [3] and provide a system wide
logging facility to any device, running a kernel or not, with access
to the block's log entry port(s). Since each trace message has a
timestamp is it possible to correlate events happening in the entire
system rather than being confined to the logging facility of a single
entity.

This patch is using a very simple "stm_source" introduced in [2] to
duplicate the output of the trace event subsystem to an STM, in this
case coresight STM. That way logging information generated by the
trace event subsystem and gathered in the coresight sink can be used
in conjunction with trace data from other board components, also
collected in the same trace sink. This example is using coresight but
the same would apply to any architecture wishing to do the same.

The goal of this RFC is to solicit comments on the method used to
connect trace event logging with STMs (using the generic STM API)
rather than function "stm_ftrace_write()" itself, which was provided
for completeness of the proof of concept only.

I'm eager to see your comments on this, and if you have some good
ideas that can slow down the overhead, please let me know. Any
questions are also welcome.

Thanks,
Chunyan


[1]. https://lkml.org/lkml/2015/2/4/729
[2]. http://comments.gmane.org/gmane.linux.kernel/1914526
[3]. http://mipi.org/specifications/debug#STP

Changes from RFC v1:
- Marked module init/exit functions with __init/__exit key word
according to the comments from Paul Bolle

Chunyan Zhang (2):
Trace log handler for logging into STM blocks
Introduce trace log output function for STM

Mathieu Poirier (1):
STM trace event: Adding generic buffer interface driver

drivers/stm/Kconfig | 11 +++++
drivers/stm/Makefile | 2 +
drivers/stm/stm_trace_event.c | 46 +++++++++++++++++++
include/linux/ftrace_event.h | 15 +++++++
include/trace/ftrace.h | 47 +++++++++++++++++++
kernel/trace/Makefile | 1 +
kernel/trace/trace_output_stm.c | 99 +++++++++++++++++++++++++++++++++++++++++
7 files changed, 221 insertions(+)
create mode 100644 drivers/stm/stm_trace_event.c
create mode 100644 kernel/trace/trace_output_stm.c

--
1.9.1


2015-06-16 07:06:49

by Chunyan Zhang

[permalink] [raw]
Subject: [RFC PATCH v2 1/3] STM trace event: Adding generic buffer interface driver

From: Mathieu Poirier <[email protected]>

This patch adds a driver that models itself as an stm_source and
who's sole purpose is to export an interface to the rest of the
kernel. Once the stm and stm_source have been linked via sysfs,
everything that is passed to the interface will endup in the STM
trace engine.

Signed-off-by: Mathieu Poirier <[email protected]>
Signed-off-by: Chunyan Zhang <[email protected]>
---
drivers/stm/Kconfig | 11 +++++++++++
drivers/stm/Makefile | 2 ++
drivers/stm/stm_trace_event.c | 46 +++++++++++++++++++++++++++++++++++++++++++
3 files changed, 59 insertions(+)
create mode 100644 drivers/stm/stm_trace_event.c

diff --git a/drivers/stm/Kconfig b/drivers/stm/Kconfig
index 6f2db70..8ead418 100644
--- a/drivers/stm/Kconfig
+++ b/drivers/stm/Kconfig
@@ -25,3 +25,14 @@ config STM_SOURCE_CONSOLE

If you want to send kernel console messages over STM devices,
say Y.
+
+config STM_TRACE_EVENT
+ tristate "Redirect/copy the output from kernel trace event to STM engine"
+ depends on STM
+ help
+ This option can be used to redirect or copy the output from kernel trace
+ event to STM engine. Enabling this option will introduce a slight
+ timing effect.
+
+ If you want to send kernel trace event messages over STM devices,
+ say Y.
diff --git a/drivers/stm/Makefile b/drivers/stm/Makefile
index 74baf59..55b152c 100644
--- a/drivers/stm/Makefile
+++ b/drivers/stm/Makefile
@@ -5,3 +5,5 @@ stm_core-y := core.o policy.o
obj-$(CONFIG_STM_DUMMY) += dummy_stm.o

obj-$(CONFIG_STM_SOURCE_CONSOLE) += console.o
+
+obj-$(CONFIG_STM_TRACE_EVENT) += stm_trace_event.o
diff --git a/drivers/stm/stm_trace_event.c b/drivers/stm/stm_trace_event.c
new file mode 100644
index 0000000..bc77dae
--- /dev/null
+++ b/drivers/stm/stm_trace_event.c
@@ -0,0 +1,46 @@
+/*
+ * Simple kernel driver to link kernel trace event and an STM device
+ * Copyright (c) 2015, Linaro Ltd.
+ *
+ * This program is free software; you can redistribute it and/or modify it
+ * under the terms and conditions of the GNU General Public License,
+ * version 2, as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
+ * more details.
+ */
+
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/slab.h>
+#include <linux/console.h>
+#include <linux/stm.h>
+
+static struct stm_source_data stm_trace_event_data = {
+ .name = "stm_trace_event",
+ .nr_chans = 1,
+};
+
+void stm_trace_event_write(const char *buf, unsigned len)
+{
+ stm_source_write(&stm_trace_event_data, 0, buf, len);
+}
+
+static int __init stm_trace_event_init(void)
+{
+ return stm_source_register_device(NULL, &stm_trace_event_data);
+}
+
+static void __exit stm_trace_event_exit(void)
+{
+ stm_source_unregister_device(&stm_trace_event_data);
+}
+
+module_init(stm_trace_event_init);
+module_exit(stm_trace_event_exit);
+
+MODULE_LICENSE("GPL v2");
+MODULE_DESCRIPTION("stm_trace_event driver");
+MODULE_AUTHOR("Mathieu Poirier <[email protected]>");
--
1.9.1

2015-06-16 07:06:54

by Chunyan Zhang

[permalink] [raw]
Subject: [RFC PATCH v2 2/3] Trace log handler for logging into STM blocks

Adding the function 'trace_event_stm_output_##call' for printing events
trace log into STM blocks.

This patch also added a function call at where the events have been
committed to ring buffer to export the trace event information to
STM blocks.

Signed-off-by: Chunyan Zhang <[email protected]>
---
include/linux/ftrace_event.h | 15 ++++++++++++++
include/trace/ftrace.h | 47 ++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 62 insertions(+)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 46e83c2..f0c7426 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -14,6 +14,7 @@ struct trace_buffer;
struct tracer;
struct dentry;
struct bpf_prog;
+struct trace_buffer_stm;

struct trace_print_flags {
unsigned long mask;
@@ -304,6 +305,9 @@ struct ftrace_event_call {
*/
int flags; /* static flags of different events */

+ void (*output_stm)(struct trace_seq *tmp_seq, void *entry,
+ struct trace_buffer_stm *tb);
+
#ifdef CONFIG_PERF_EVENTS
int perf_refcount;
struct hlist_head __percpu *perf_events;
@@ -423,6 +427,17 @@ enum event_trigger_type {
ETT_EVENT_ENABLE = (1 << 3),
};

+#ifdef CONFIG_STM_TRACE_EVENT
+extern void trace_event_stm_log(struct ftrace_event_buffer *fbuffer);
+extern void trace_event_buf_vprintf(struct trace_buffer_stm *tb,
+ const char *fmt, ...) __attribute__ ((weak));
+extern void stm_trace_event_write(const char *buf, unsigned len);
+#else
+static inline void trace_event_stm_log(struct ftrace_event_buffer *fbuffer) {}
+static inline void trace_event_buf_vprintf(struct trace_buffer_stm *tb,
+ const char *fmt, ...) {}
+#endif
+
extern int filter_match_preds(struct event_filter *filter, void *rec);

extern int filter_check_discard(struct ftrace_event_file *file, void *rec,
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 37d4b10..20c7228 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -303,6 +303,50 @@ TRACE_MAKE_SYSTEM_STR();

#undef DECLARE_EVENT_CLASS
#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print) \
+static notrace void \
+trace_event_stm_output_##call(struct trace_seq *tmp_seq, \
+ void *entry, \
+ struct trace_buffer_stm *trace_buf) \
+{ \
+ struct ftrace_raw_##call *field = entry; \
+ struct trace_seq *p = tmp_seq; \
+ \
+ trace_seq_init(p); \
+ \
+ trace_event_buf_vprintf(trace_buf, print); \
+ \
+ return; \
+}
+
+#undef DEFINE_EVENT_PRINT
+#define DEFINE_EVENT_PRINT(template, call, proto, args, print) \
+static notrace void \
+trace_event_stm_output_##call(struct trace_seq *tmp_seq, \
+ void *entry, \
+ struct trace_buffer_stm *trace_buf) \
+{ \
+ struct trace_seq *p = tmp_seq; \
+ struct trace_entry *ent = entry; \
+ struct ftrace_raw_##template *field; \
+ \
+ if (ent->type != event_##call.event.type) { \
+ WARN_ON_ONCE(1); \
+ return; \
+ } \
+ \
+ field = (typeof(field))entry; \
+ \
+ trace_seq_init(p); \
+ \
+ trace_event_buf_vprintf(trace_buf, print); \
+ \
+ return; \
+}
+
+#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
+
+#undef DECLARE_EVENT_CLASS
+#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print) \
static notrace enum print_line_t \
ftrace_raw_output_##call(struct trace_iterator *iter, int flags, \
struct trace_event *trace_event) \
@@ -683,6 +727,7 @@ ftrace_raw_event_##call(void *__data, proto) \
{ assign; } \
\
ftrace_event_buffer_commit(&fbuffer); \
+ trace_event_stm_log(&fbuffer); \
}
/*
* The ftrace_test_probe is compiled out, it is only here as a build time check
@@ -742,6 +787,7 @@ static struct ftrace_event_call __used event_##call = { \
.event.funcs = &ftrace_event_type_funcs_##template, \
.print_fmt = print_fmt_##template, \
.flags = TRACE_EVENT_FL_TRACEPOINT, \
+ .output_stm = trace_event_stm_output_##template, \
}; \
static struct ftrace_event_call __used \
__attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
@@ -759,6 +805,7 @@ static struct ftrace_event_call __used event_##call = { \
.event.funcs = &ftrace_event_type_funcs_##call, \
.print_fmt = print_fmt_##call, \
.flags = TRACE_EVENT_FL_TRACEPOINT, \
+ .output_stm = trace_event_stm_output_##call, \
}; \
static struct ftrace_event_call __used \
__attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
--
1.9.1

2015-06-16 07:07:00

by Chunyan Zhang

[permalink] [raw]
Subject: [RFC PATCH v2 3/3] Introduce trace log output function for STM

This patch introduced a few functions to print the event trace log to
STM buffer when the trace event happen and the event information
would be committed to ring buffer.

Before outputting the trace log to STM, we have to get the human readable
trace log content and print it into a local buffer in the format of a
string, the function 'trace_event_buf_vprintf()' is just for this purpose.

Signed-off-by: Chunyan Zhang <[email protected]>
---
kernel/trace/Makefile | 1 +
kernel/trace/trace_output_stm.c | 99 +++++++++++++++++++++++++++++++++++++++++
2 files changed, 100 insertions(+)
create mode 100644 kernel/trace/trace_output_stm.c

diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 9b1044e..002de34 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -67,4 +67,5 @@ obj-$(CONFIG_UPROBE_EVENT) += trace_uprobe.o

obj-$(CONFIG_TRACEPOINT_BENCHMARK) += trace_benchmark.o

+obj-$(CONFIG_STM_TRACE_EVENT) += trace_output_stm.o
libftrace-y := ftrace.o
diff --git a/kernel/trace/trace_output_stm.c b/kernel/trace/trace_output_stm.c
new file mode 100644
index 0000000..1cf6d87
--- /dev/null
+++ b/kernel/trace/trace_output_stm.c
@@ -0,0 +1,99 @@
+#include <linux/ftrace_event.h>
+#include <linux/mutex.h>
+#include <linux/slab.h>
+#include "trace.h"
+
+#define STM_OUTPUT_STRLEN 128
+
+/* store the event trace log for STM */
+struct trace_buffer_stm {
+ char buffer[STM_OUTPUT_STRLEN];
+ unsigned int used_len;
+ unsigned int size;
+};
+
+static struct trace_buffer_stm *trace_event_stm_buffer;
+static struct trace_seq *stm_tmp_seq;
+static int stm_buffers_allocated;
+
+void trace_event_buf_vprintf(struct trace_buffer_stm *tb, const char *fmt, ...)
+{
+ va_list ap;
+ char *buffer = tb->buffer + tb->used_len;
+ unsigned int size = tb->size - tb->used_len;
+
+ va_start(ap, fmt);
+ tb->used_len += vsnprintf(buffer, size, fmt, ap);
+ va_end(ap);
+}
+EXPORT_SYMBOL_GPL(trace_event_buf_vprintf);
+
+static inline void stm_buf_reset(struct trace_buffer_stm *tb)
+{
+ tb->used_len = 0;
+}
+
+void trace_event_stm_log(struct ftrace_event_buffer *fbuffer)
+{
+
+ struct trace_seq *p = stm_tmp_seq;
+ struct trace_buffer_stm *tb;
+ struct ftrace_event_call *event_call = fbuffer->ftrace_file->event_call;
+ struct trace_entry *entry = (struct trace_entry *)fbuffer->entry;
+
+ if (!stm_buffers_allocated)
+ return;
+
+ tb = trace_event_stm_buffer;
+
+ if (event_call->output_stm)
+ event_call->output_stm(p, entry, tb);
+
+ stm_trace_event_write(tb->buffer, tb->used_len);
+
+ stm_buf_reset(tb);
+}
+EXPORT_SYMBOL_GPL(trace_event_stm_log);
+
+static int alloc_stm_tmp_seq(void)
+{
+ struct trace_seq *seq;
+
+ seq = kzalloc(sizeof(struct trace_seq), GFP_KERNEL);
+ if (!seq)
+ return -ENOMEM;
+
+ stm_tmp_seq = seq;
+
+ return 0;
+}
+
+static int alloc_stm_trace_buffer(void)
+{
+ struct trace_buffer_stm *buffer;
+
+ buffer = kzalloc(sizeof(struct trace_buffer_stm), GFP_KERNEL);
+ if (!buffer)
+ return -ENOMEM;
+
+ buffer->used_len = 0;
+ buffer->size = ARRAY_SIZE(buffer->buffer);
+
+ trace_event_stm_buffer = buffer;
+
+ return 0;
+}
+
+static __init int trace_stm_init_buffers(void)
+{
+ if (alloc_stm_trace_buffer())
+ return -ENOMEM;
+
+ if (alloc_stm_tmp_seq())
+ return -ENOMEM;
+
+ stm_buffers_allocated = 1;
+
+ return 0;
+}
+fs_initcall(trace_stm_init_buffers);
--
1.9.1