[RFC PATCH v3 0/4] Integration of trace events with System Trace IP blocks

[RFC PATCH v3 0/4] Integration of trace events with System Trace IP blocks

[Chunyan Zhang]

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 v2:
	- Revised some types and variable's name according to the
	  code of v4.2-rc1
	- Sorted this patch-set based on the v4.2-rc1
	- Splited the patch 2/3 of my last patch-set to make code can
	   be compiled after each patch is applied in order.

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

Chunyan Zhang (3):
  trace: Add an entry for printing trace log to STM
  trace: Introduce trace log output function for STM
  trace: Trace log handler for logging into STM blocks

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/trace_events.h    | 16 +++++++
 include/trace/perf.h            |  3 ++
 include/trace/trace_events.h    | 44 ++++++++++++++++++
 kernel/trace/Makefile           |  1 +
 kernel/trace/trace_output_stm.c | 99 +++++++++++++++++++++++++++++++++++++++++
 8 files changed, 222 insertions(+)
 create mode 100644 drivers/stm/stm_trace_event.c
 create mode 100644 kernel/trace/trace_output_stm.c

-- 
1.9.1

[RFC PATCH v3 1/4] STM trace event: Adding generic buffer interface driver

[Chunyan Zhang]

From: Mathieu Poirier <mathieu.poirier@linaro.org>

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 <mathieu.poirier@linaro.org>
Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
---
 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 <mathieu.poirier@linaro.org>");
-- 
1.9.1

[RFC PATCH v3 2/4] trace: Add an entry for printing trace log to STM

[Chunyan Zhang]

output_stm is a link which is used to connect trace event
logging with STMs, will be used in the upcoming patches.

Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
---
 include/linux/trace_events.h | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 1063c85..28dcdff 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.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;
@@ -293,6 +294,9 @@ struct trace_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;
@@ -412,6 +416,10 @@ enum event_trigger_type {
 	ETT_EVENT_ENABLE	= (1 << 3),
 };
 
+#ifdef CONFIG_STM_TRACE_EVENT
+extern void stm_trace_event_write(const char *buf, unsigned len);
+#endif
+
 extern int filter_match_preds(struct event_filter *filter, void *rec);
 
 extern int filter_check_discard(struct trace_event_file *file, void *rec,
-- 
1.9.1

[RFC PATCH v3 3/4] trace: Introduce trace log output function for STM

[Chunyan Zhang]

This patch introduced a few functions to print the event trace log to
STM buffer when the trace event happened and the event information
was 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 <zhang.chunyan@linaro.org>
---
 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..689c6d5
--- /dev/null
+++ b/kernel/trace/trace_output_stm.c
@@ -0,0 +1,99 @@
+#include <linux/trace_events.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 trace_event_buffer *buffer)
+{
+
+	struct trace_seq *p = stm_tmp_seq;
+	struct trace_buffer_stm *tb;
+	struct trace_event_call *event_call = buffer->trace_file->event_call;
+	struct trace_entry *entry = (struct trace_entry *)buffer->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

[RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Chunyan Zhang]

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

This patch also adds 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 <zhang.chunyan@linaro.org>
---
 include/linux/trace_events.h |  8 ++++++++
 include/trace/perf.h         |  3 +++
 include/trace/trace_events.h | 44 ++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 55 insertions(+)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 28dcdff..705bd4e 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -418,6 +418,14 @@ enum event_trigger_type {
 
 #ifdef CONFIG_STM_TRACE_EVENT
 extern void stm_trace_event_write(const char *buf, unsigned len);
+extern void trace_event_stm_log(struct trace_event_buffer *buffer);
+extern void trace_event_buf_vprintf(struct trace_buffer_stm *tb,
+			    const char *fmt, ...) __attribute__ ((weak));
+#else
+static inline void trace_event_stm_log(struct trace_event_buffer *buffer) {}
+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);
diff --git a/include/trace/perf.h b/include/trace/perf.h
index 1b5443c..79906de 100644
--- a/include/trace/perf.h
+++ b/include/trace/perf.h
@@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)			\
 	{ assign; }							\
 									\
 	trace_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
@@ -234,6 +235,7 @@ static struct trace_event_call __used event_##call = {			\
 	.event.funcs		= &trace_event_type_funcs_##template,	\
 	.print_fmt		= print_fmt_##template,			\
 	.flags			= TRACE_EVENT_FL_TRACEPOINT,		\
+	.output_stm		= trace_event_stm_output_##template,	\
 };									\
 static struct trace_event_call __used					\
 __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
@@ -251,6 +253,7 @@ static struct trace_event_call __used event_##call = {			\
 	.event.funcs		= &trace_event_type_funcs_##call,	\
 	.print_fmt		= print_fmt_##call,			\
 	.flags			= TRACE_EVENT_FL_TRACEPOINT,		\
+	.output_stm		= trace_event_stm_output_##call,	\
 };									\
 static struct trace_event_call __used					\
 __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index 43be3b0..db4d8a7 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.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 trace_event_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 trace_event_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					\
 trace_raw_output_##call(struct trace_iterator *iter, int flags,		\
 			struct trace_event *trace_event)		\
-- 
1.9.1

Re: [RFC PATCH v3 0/4] Integration of trace events with System Trace IP blocks

[Alexander Shishkin]

Chunyan Zhang <zhang.chunyan@linaro.org> writes:

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

Hi,

A brief looks tells me that your code is based on an older version of
mine. Can you please update so that our work is more in sync and it
would also make it easier for me to review.

Thanks,
--
Alex

Re: [RFC PATCH v3 2/4] trace: Add an entry for printing trace log to STM

[Steven Rostedt]

On Tue,  7 Jul 2015 18:10:41 +0800
Chunyan Zhang <zhang.chunyan@linaro.org> wrote:

> output_stm is a link which is used to connect trace event
> logging with STMs, will be used in the upcoming patches.
> 
> Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
> ---
>  include/linux/trace_events.h | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> index 1063c85..28dcdff 100644
> --- a/include/linux/trace_events.h
> +++ b/include/linux/trace_events.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;
> @@ -293,6 +294,9 @@ struct trace_event_call {
>  	 */
>  	int			flags; /* static flags of different events */
>  
> +	void (*output_stm)(struct trace_seq *tmp_seq, void *entry,
> +			   struct trace_buffer_stm *tb);
> +

Shouldn't the above also have a #ifdef CONFIG_STM_TRACE_EVENT
encompassing it? Otherwise we are adding 8 bytes to every trace event.

-- Steve

>  #ifdef CONFIG_PERF_EVENTS
>  	int				perf_refcount;
>  	struct hlist_head __percpu	*perf_events;
> @@ -412,6 +416,10 @@ enum event_trigger_type {
>  	ETT_EVENT_ENABLE	= (1 << 3),
>  };
>  
> +#ifdef CONFIG_STM_TRACE_EVENT
> +extern void stm_trace_event_write(const char *buf, unsigned len);
> +#endif
> +
>  extern int filter_match_preds(struct event_filter *filter, void *rec);
>  
>  extern int filter_check_discard(struct trace_event_file *file, void *rec,

Re: [RFC PATCH v3 0/4] Integration of trace events with System Trace IP blocks

[Chunyan Zhang]

On Tue, Jul 7, 2015 at 7:12 PM, Alexander Shishkin
<alexander.shishkin@linux.intel.com> wrote:
> Chunyan Zhang <zhang.chunyan@linaro.org> writes:
>
>> 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.
>
> Hi,
>
> A brief looks tells me that your code is based on an older version of
> mine. Can you please update so that our work is more in sync and it
> would also make it easier for me to review.
>

Ok, will update in the next version of patch-set.

Best regards,
Chunyan

> Thanks,
> --
> Alex

Re: [RFC PATCH v3 2/4] trace: Add an entry for printing trace log to STM

[Chunyan Zhang]

On Tue, Jul 7, 2015 at 11:58 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Tue,  7 Jul 2015 18:10:41 +0800
> Chunyan Zhang <zhang.chunyan@linaro.org> wrote:
>
>> output_stm is a link which is used to connect trace event
>> logging with STMs, will be used in the upcoming patches.
>>
>> Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
>> ---
>>  include/linux/trace_events.h | 8 ++++++++
>>  1 file changed, 8 insertions(+)
>>
>> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
>> index 1063c85..28dcdff 100644
>> --- a/include/linux/trace_events.h
>> +++ b/include/linux/trace_events.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;
>> @@ -293,6 +294,9 @@ struct trace_event_call {
>>        */
>>       int                     flags; /* static flags of different events */
>>
>> +     void (*output_stm)(struct trace_seq *tmp_seq, void *entry,
>> +                        struct trace_buffer_stm *tb);
>> +
>
> Shouldn't the above also have a #ifdef CONFIG_STM_TRACE_EVENT
> encompassing it? Otherwise we are adding 8 bytes to every trace event.
>

Agree. I will address this in the next version of patches.

BTW, in patch 3/4, I defined a structure variable like this:
   "static struct trace_seq *stm_tmp_seq;"
It was actually the first parameter of " trace_event_stm_output_##call
" which was in the patch 4/4.

Do you think if it is an accept way to handle like this? Whether we
would have a better way instead of defining a structure variable
locally?

Thanks,
Chunyan


> -- Steve
>
>>  #ifdef CONFIG_PERF_EVENTS
>>       int                             perf_refcount;
>>       struct hlist_head __percpu      *perf_events;
>> @@ -412,6 +416,10 @@ enum event_trigger_type {
>>       ETT_EVENT_ENABLE        = (1 << 3),
>>  };
>>
>> +#ifdef CONFIG_STM_TRACE_EVENT
>> +extern void stm_trace_event_write(const char *buf, unsigned len);
>> +#endif
>> +
>>  extern int filter_match_preds(struct event_filter *filter, void *rec);
>>
>>  extern int filter_check_discard(struct trace_event_file *file, void *rec,
>

Re: [RFC PATCH v3 0/4] Integration of trace events with System Trace IP blocks

[Alexander Shishkin]

Chunyan Zhang <zhang.chunyan@linaro.org> writes:

> On Tue, Jul 7, 2015 at 7:12 PM, Alexander Shishkin
> <alexander.shishkin@linux.intel.com> wrote:
>> Chunyan Zhang <zhang.chunyan@linaro.org> writes:
>>
>>> 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.
>>
>> Hi,
>>
>> A brief looks tells me that your code is based on an older version of
>> mine. Can you please update so that our work is more in sync and it
>> would also make it easier for me to review.
>>
>
> Ok, will update in the next version of patch-set.

Thanks!

Re: [RFC PATCH v3 1/4] STM trace event: Adding generic buffer interface driver

[Alexander Shishkin]

Chunyan Zhang <zhang.chunyan@linaro.org> writes:

> From: Mathieu Poirier <mathieu.poirier@linaro.org>
>
> 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 <mathieu.poirier@linaro.org>
> Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
> ---
>  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,

One question is: do we want to cram ftrace data from all cpus into one
channel or use a channel per cpu?

Regards,
--
Alex

Re: [RFC PATCH v3 1/4] STM trace event: Adding generic buffer interface driver

[Peter Zijlstra]

On Tue, Jul 07, 2015 at 06:10:40PM +0800, Chunyan Zhang wrote:
> +config STM_TRACE_EVENT
> +	tristate "Redirect/copy the output from kernel trace event to STM engine"

How does tristate make sense here? You're using it unconditionally for
in-kernel tracepoints. This must be bool, which in turn makes the whole
STM thing bool afaiu.

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Peter Zijlstra]

On Tue, Jul 07, 2015 at 06:10:43PM +0800, Chunyan Zhang wrote:
> Add the function 'trace_event_stm_output_##call' for printing events
> trace log into STM blocks.
> 
> This patch also adds a function call at where the events have been
> committed to ring buffer to export the trace event information to
> STM blocks.

So then you have two copies of the data, why that? Would a scheme were
data either goes to the STM or the regular buffer not make much more
sense?

> +++ b/include/trace/perf.h
> @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)			\
>  	{ assign; }							\
>  									\
>  	trace_event_buffer_commit(&fbuffer);				\
> +	trace_event_stm_log(&fbuffer);					\

This makes every trace event slower.

>  }
>  /*
>   * The ftrace_test_probe is compiled out, it is only here as a build time check

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Chunyan Zhang]

On Wed, Jul 8, 2015 at 8:31 PM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Tue, Jul 07, 2015 at 06:10:43PM +0800, Chunyan Zhang wrote:
>> Add the function 'trace_event_stm_output_##call' for printing events
>> trace log into STM blocks.
>>
>> This patch also adds a function call at where the events have been
>> committed to ring buffer to export the trace event information to
>> STM blocks.
>
> So then you have two copies of the data, why that? Would a scheme were
> data either goes to the STM or the regular buffer not make much more
> sense?

We don't have two copies when we export the trace logs to STM, because
the event trace logs what we can see by catting the Ftrace files
haven't been generated at that moment.

>
>> +++ b/include/trace/perf.h
>> @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)                 \
>>       { assign; }                                                     \
>>                                                                       \
>>       trace_event_buffer_commit(&fbuffer);                            \
>> +     trace_event_stm_log(&fbuffer);                                  \
>
> This makes every trace event slower.

It doesn't actually, you may decide if enable this feature, the trace
event will not be slowed if STM_TRACE_EVENT is not selected.
But if this feature enabled, it will indeed take more time than
without this feature.

Best regards,
Chunyan

>
>>  }
>>  /*
>>   * The ftrace_test_probe is compiled out, it is only here as a build time check

Re: [RFC PATCH v3 1/4] STM trace event: Adding generic buffer interface driver

[Alexander Shishkin]

Peter Zijlstra <peterz@infradead.org> writes:

> On Tue, Jul 07, 2015 at 06:10:40PM +0800, Chunyan Zhang wrote:
>> +config STM_TRACE_EVENT
>> +	tristate "Redirect/copy the output from kernel trace event to STM engine"
>
> How does tristate make sense here? You're using it unconditionally for
> in-kernel tracepoints. This must be bool, which in turn makes the whole
> STM thing bool afaiu.

That would make the whole STM thing a bool. I'd rather we used stm
output *conditionally* by somehow plugging into tracepoint output, say
with a jump label or something. Haven't had time to think about it yet.

Regards,
--
Alex

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Steven Rostedt]

On Wed, 8 Jul 2015 14:31:48 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, Jul 07, 2015 at 06:10:43PM +0800, Chunyan Zhang wrote:
> > Add the function 'trace_event_stm_output_##call' for printing events
> > trace log into STM blocks.
> > 
> > This patch also adds a function call at where the events have been
> > committed to ring buffer to export the trace event information to
> > STM blocks.
> 
> So then you have two copies of the data, why that? Would a scheme were
> data either goes to the STM or the regular buffer not make much more
> sense?
> 
> > +++ b/include/trace/perf.h
> > @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)			\
> >  	{ assign; }							\
> >  									\
> >  	trace_event_buffer_commit(&fbuffer);				\
> > +	trace_event_stm_log(&fbuffer);					\
> 
> This makes every trace event slower.

Of course this could use a jump label.

But I agree, I think a switch to which buffer it should be sent to is
better. I could come up with a way to make the buffer more generic, and
have it switch between where the event is recorded.

-- Steve

> 
> >  }
> >  /*
> >   * The ftrace_test_probe is compiled out, it is only here as a build time check

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Ingo Molnar]

* Chunyan Zhang <zhang.chunyan@linaro.org> wrote:

> >> +++ b/include/trace/perf.h
> >> @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)                 \
> >>       { assign; }                                                     \
> >>                                                                       \
> >>       trace_event_buffer_commit(&fbuffer);                            \
> >> +     trace_event_stm_log(&fbuffer);                                  \
> >
> > This makes every trace event slower.
> 
> It doesn't actually, you may decide if enable this feature, the trace event will 
> not be slowed if STM_TRACE_EVENT is not selected.

It slows down everyone if a distro enables this feature - that's not acceptable.

Thanks,

	Ingo

Re: [RFC PATCH v3 1/4] STM trace event: Adding generic buffer interface driver

[Mathieu Poirier]

On 8 July 2015 at 04:23, Alexander Shishkin
<alexander.shishkin@linux.intel.com> wrote:
> Chunyan Zhang <zhang.chunyan@linaro.org> writes:
>
>> From: Mathieu Poirier <mathieu.poirier@linaro.org>
>>
>> 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 <mathieu.poirier@linaro.org>
>> Signed-off-by: Chunyan Zhang <zhang.chunyan@linaro.org>
>> ---
>>  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,
>
> One question is: do we want to cram ftrace data from all cpus into one
> channel or use a channel per cpu?

That's the perennial question.  Even one channel per cpu may not be
sufficient... Some configuration may want to use one channel per
application.  We should favour the solution that offers the most
flexibility - the above was for the RFC only.

>
> Regards,
> --
> Alex

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Chunyan Zhang]

On Wed, Jul 8, 2015 at 9:19 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 8 Jul 2015 14:31:48 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
>
>> On Tue, Jul 07, 2015 at 06:10:43PM +0800, Chunyan Zhang wrote:
>> > Add the function 'trace_event_stm_output_##call' for printing events
>> > trace log into STM blocks.
>> >
>> > This patch also adds a function call at where the events have been
>> > committed to ring buffer to export the trace event information to
>> > STM blocks.
>>
>> So then you have two copies of the data, why that? Would a scheme were
>> data either goes to the STM or the regular buffer not make much more
>> sense?
>>
>> > +++ b/include/trace/perf.h
>> > @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)                       \
>> >     { assign; }                                                     \
>> >                                                                     \
>> >     trace_event_buffer_commit(&fbuffer);                            \
>> > +   trace_event_stm_log(&fbuffer);                                  \
>>
>> This makes every trace event slower.
>
> Of course this could use a jump label.
>
> But I agree, I think a switch to which buffer it should be sent to is
> better. I could come up with a way to make the buffer more generic, and
> have it switch between where the event is recorded.

Thanks, Steve.

It cannot be better if there will be a way to  meet the requirements
both of Trace event and STM.
I also don't want to slow down the trace original speed after enable
this feature. But I didn't find any way to achieve this ideal effect.
This is just why I sent out this RFCs.

And I'd also like to explain a fact about STM, which would likely need
only a string of trace messages directly when the trace events
happened because of its architecture.

Anyway, everything is possible, let's brainstorm!
If you have any question about STM, please let me know.

Many thanks,
Chunyan

>
> -- Steve
>
>>
>> >  }
>> >  /*
>> >   * The ftrace_test_probe is compiled out, it is only here as a build time check
>

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Chunyan Zhang]

On Wed, Jul 8, 2015 at 9:19 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 8 Jul 2015 14:31:48 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
>
>> On Tue, Jul 07, 2015 at 06:10:43PM +0800, Chunyan Zhang wrote:
>> > Add the function 'trace_event_stm_output_##call' for printing events
>> > trace log into STM blocks.
>> >
>> > This patch also adds a function call at where the events have been
>> > committed to ring buffer to export the trace event information to
>> > STM blocks.
>>
>> So then you have two copies of the data, why that? Would a scheme were
>> data either goes to the STM or the regular buffer not make much more
>> sense?
>>
>> > +++ b/include/trace/perf.h
>> > @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)                       \
>> >     { assign; }                                                     \
>> >                                                                     \
>> >     trace_event_buffer_commit(&fbuffer);                            \
>> > +   trace_event_stm_log(&fbuffer);                                  \
>>
>> This makes every trace event slower.
>
> Of course this could use a jump label.
>
> But I agree, I think a switch to which buffer it should be sent to is
> better. I could come up with a way to make the buffer more generic, and
> have it switch between where the event is recorded.
>

Hello Steve,

Please excuse my disturbing you again.

May I get more details of how you want the code (including Trace Event
and STM subsystem) will be reworked?
I know you are very busy, maybe I can more or less help with
something. I'm eager to do that, but the problem for now is I think
I'm not in the same level for the understanding of next work we need
to do.
Do you have an exact solution already? or some ideas you want me to try?


Looking forward to your reply, thank you!
Chunyan


> -- Steve
>
>>
>> >  }
>> >  /*
>> >   * The ftrace_test_probe is compiled out, it is only here as a build time check
>

Re: [RFC PATCH v3 3/4] trace: Introduce trace log output function for STM

[Steven Rostedt]

On Tue,  7 Jul 2015 18:10:42 +0800
Chunyan Zhang <zhang.chunyan@linaro.org> wrote:

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

This needs to free trace_event_stm_buffer.

-- Steve

> +		return -ENOMEM;
> +
> +	stm_buffers_allocated = 1;
> +
> +	return 0;
> +}
> +fs_initcall(trace_stm_init_buffers);

Re: [RFC PATCH v3 4/4] trace: Trace log handler for logging into STM blocks

[Steven Rostedt]

On Tue,  7 Jul 2015 18:10:43 +0800
Chunyan Zhang <zhang.chunyan@linaro.org> wrote:

> Add the function 'trace_event_stm_output_##call' for printing events
> trace log into STM blocks.
> 
> This patch also adds 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 <zhang.chunyan@linaro.org>
> ---
>  include/linux/trace_events.h |  8 ++++++++
>  include/trace/perf.h         |  3 +++
>  include/trace/trace_events.h | 44 ++++++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 55 insertions(+)
> 
> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> index 28dcdff..705bd4e 100644
> --- a/include/linux/trace_events.h
> +++ b/include/linux/trace_events.h
> @@ -418,6 +418,14 @@ enum event_trigger_type {
>  
>  #ifdef CONFIG_STM_TRACE_EVENT
>  extern void stm_trace_event_write(const char *buf, unsigned len);
> +extern void trace_event_stm_log(struct trace_event_buffer *buffer);
> +extern void trace_event_buf_vprintf(struct trace_buffer_stm *tb,
> +			    const char *fmt, ...) __attribute__ ((weak));
> +#else
> +static inline void trace_event_stm_log(struct trace_event_buffer *buffer) {}
> +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);
> diff --git a/include/trace/perf.h b/include/trace/perf.h
> index 1b5443c..79906de 100644
> --- a/include/trace/perf.h
> +++ b/include/trace/perf.h
> @@ -175,6 +175,7 @@ trace_event_raw_event_##call(void *__data, proto)			\
>  	{ assign; }							\
>  									\
>  	trace_event_buffer_commit(&fbuffer);				\
> +	trace_event_stm_log(&fbuffer);					\

This could be moved into trace_event_buffer_commit().

>  }
>  /*
>   * The ftrace_test_probe is compiled out, it is only here as a build time check
> @@ -234,6 +235,7 @@ static struct trace_event_call __used event_##call = {			\
>  	.event.funcs		= &trace_event_type_funcs_##template,	\
>  	.print_fmt		= print_fmt_##template,			\
>  	.flags			= TRACE_EVENT_FL_TRACEPOINT,		\
> +	.output_stm		= trace_event_stm_output_##template,	\
>  };									\
>  static struct trace_event_call __used					\
>  __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
> @@ -251,6 +253,7 @@ static struct trace_event_call __used event_##call = {			\
>  	.event.funcs		= &trace_event_type_funcs_##call,	\
>  	.print_fmt		= print_fmt_##call,			\
>  	.flags			= TRACE_EVENT_FL_TRACEPOINT,		\
> +	.output_stm		= trace_event_stm_output_##call,	\
>  };									\
>  static struct trace_event_call __used					\
>  __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
> diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> index 43be3b0..db4d8a7 100644
> --- a/include/trace/trace_events.h
> +++ b/include/trace/trace_events.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 trace_event_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 trace_event_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;								\
> +}

To save a lot of code, as this is duplicated for hundreds of events,
you could simply reuse the trace_raw_output_##call(), by passing in
a trace_iterator() with just enough to get through it. We can even add
a flag to not do the output_prep() work, if need be.

-- Steve


> +
> +#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					\
>  trace_raw_output_##call(struct trace_iterator *iter, int flags,		\
>  			struct trace_event *trace_event)		\