tracing: reduce latency and remove percpu trace_seq

PATCH In review Lai Jiangshan 2 participants 7 messages Jun 3, 2010 – Jul 23, 2010

Subsystems (2)

Tracing ftrace

lore

Share & tools

lore

Lai Jiangshan

author

2010-06-03 10:26 UTC #0 lore raw

PATCH 1/1 tracing: reduce latency and remove percpu trace_seq

__print_flags() and __print_symbolic() use percpu trace_seq:

1) Its memory is allocated at compile time, it wastes memory if we don't use tracing.
2) It is percpu data and it wastes more memory for multi-cpus system.
3) It disables preemption when it executes its core routine "trace_seq_printf(s, "%s: ", #call);" and introduces latency.

So we move this trace_seq to struct trace_iterator.

Signed-off-by Lai Jiangshan <[email protected]>

---
 include/linux/ftrace_event.h |    5 +++--
 include/trace/ftrace.h       |   12 +++---------
 kernel/trace/trace_output.c  |    3 ---
 3 files changed, 6 insertions(+), 14 deletions(-)

include/linux/ftrace_event.h +3 -2

index 3167f2d..25e264d 100644
@@ -11,8 +11,6 @@ struct trace_array;
 struct tracer;
 struct dentry;
 
-DECLARE_PER_CPU(struct trace_seq, ftrace_event_seq);
-
 struct trace_print_flags {
 	unsigned long		mask;
 	const char		*name;

@@ -58,6 +56,9 @@ struct trace_iterator {
 	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
 	unsigned long		iter_flags;
 
+	/* trace_seq for __print_flags() and __print_symbolic() etc. */
+	struct trace_seq	tmp_seq;
+
 	/* The below is zeroed out in pipe_read */
 	struct trace_seq	seq;
 	struct trace_entry	*ent;

include/trace/ftrace.h +3 -9

index 5a64905..19369db 100644
@@ -145,7 +145,7 @@
  *	struct trace_seq *s = &iter->seq;
  *	struct ftrace_raw_<call> *field; <-- defined in stage 1
  *	struct trace_entry *entry;
- *	struct trace_seq *p;
+ *	struct trace_seq *p = &iter->tmp_seq;
  *	int ret;
  *
  *	entry = iter->ent;

@@ -157,12 +157,10 @@
  *
  *	field = (typeof(field))entry;
  *
- *	p = &get_cpu_var(ftrace_event_seq);
  *	trace_seq_init(p);
  *	ret = trace_seq_printf(s, "%s: ", <call>);
  *	if (ret)
  *		ret = trace_seq_printf(s, <TP_printk> "\n");
- *	put_cpu();
  *	if (!ret)
  *		return TRACE_TYPE_PARTIAL_LINE;
  *

@@ -216,7 +214,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##call *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	event = container_of(trace_event, struct ftrace_event_call,	\

@@ -231,12 +229,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", event->name);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

@@ -255,7 +251,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##template *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	entry = iter->ent;						\

@@ -267,12 +263,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", #call);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

kernel/trace/trace_output.c +0 -3

index 57c1b45..1ba64d3 100644
@@ -16,9 +16,6 @@
 
 DECLARE_RWSEM(trace_event_mutex);
 
-DEFINE_PER_CPU(struct trace_seq, ftrace_event_seq);
-EXPORT_PER_CPU_SYMBOL(ftrace_event_seq);
-
 static struct hlist_head event_hash[EVENT_HASHSIZE] __read_mostly;
 
 static int next_event_type = __TRACE_LAST_TYPE + 1;

Steven Rostedt

maintainer

2010-06-03 13:36 UTC #1 lore raw

Quoted 8 lines · Lai Jiangshan

__print_flags() and __print_symbolic() use percpu trace_seq:
1) Its memory is allocated at compile time, it wastes memory if we don't use tracing.
2) It is percpu data and it wastes more memory for multi-cpus system.
3) It disables preemption when it executes its core routine "trace_seq_printf(s, "%s: ", #call);" and introduces latency.
So we move this trace_seq to struct trace_iterator.

I like the patch, except for one thing.

[ added Ted because he was the one needing this ]

Quoted 66 lines

Signed-off-by Lai Jiangshan <[email protected]>

---
 include/linux/ftrace_event.h |    5 +++--
 include/trace/ftrace.h       |   12 +++---------
 kernel/trace/trace_output.c  |    3 ---
 3 files changed, 6 insertions(+), 14 deletions(-)

include/linux/ftrace_event.h +3 -2

index 3167f2d..25e264d 100644
@@ -11,8 +11,6 @@ struct trace_array;
 struct tracer;
 struct dentry;
 
-DECLARE_PER_CPU(struct trace_seq, ftrace_event_seq);
-
 struct trace_print_flags {
 	unsigned long		mask;
 	const char		*name;

@@ -58,6 +56,9 @@ struct trace_iterator {
 	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
 	unsigned long		iter_flags;
 
+	/* trace_seq for __print_flags() and __print_symbolic() etc. */
+	struct trace_seq	tmp_seq;
+
 	/* The below is zeroed out in pipe_read */
 	struct trace_seq	seq;
 	struct trace_entry	*ent;

include/trace/ftrace.h +2 -4

index 5a64905..19369db 100644
@@ -145,7 +145,7 @@
  *	struct trace_seq *s = &iter->seq;
  *	struct ftrace_raw_<call> *field; <-- defined in stage 1
  *	struct trace_entry *entry;
- *	struct trace_seq *p;
+ *	struct trace_seq *p = &iter->tmp_seq;
  *	int ret;
  *
  *	entry = iter->ent;

@@ -157,12 +157,10 @@
  *
  *	field = (typeof(field))entry;
  *
- *	p = &get_cpu_var(ftrace_event_seq);
  *	trace_seq_init(p);
  *	ret = trace_seq_printf(s, "%s: ", <call>);
  *	if (ret)
  *		ret = trace_seq_printf(s, <TP_printk> "\n");
- *	put_cpu();
  *	if (!ret)
  *		return TRACE_TYPE_PARTIAL_LINE;
  *

@@ -216,7 +214,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##call *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	event = container_of(trace_event, struct ftrace_event_call,	\

include/trace/ftrace.h ftrace_raw_output_##call(struct trace_iterator *iter, int flags, \ · line 239

Quoted 9 lines

include/trace/ftrace.h +0 -2

@@ -231,12 +229,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", event->name);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\

The "print" in the trace_seq_printf() is the TP_printk() field of the TRACE_EVENT. I believe that there were some events (ext4?) that did things that required preemption disabled.

Ted,

Is this still the case?

-- Steve

Quoted 40 lines

include/trace/ftrace.h +1 -3

 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

@@ -255,7 +251,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##template *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	entry = iter->ent;						\

@@ -267,12 +263,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", #call);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

kernel/trace/trace_output.c +0 -3

index 57c1b45..1ba64d3 100644
@@ -16,9 +16,6 @@
 
 DECLARE_RWSEM(trace_event_mutex);
 
-DEFINE_PER_CPU(struct trace_seq, ftrace_event_seq);
-EXPORT_PER_CPU_SYMBOL(ftrace_event_seq);
-
 static struct hlist_head event_hash[EVENT_HASHSIZE] __read_mostly;
 
 static int next_event_type = __TRACE_LAST_TYPE + 1;

Lai Jiangshan

author

2010-06-04 02:24 UTC #2 lore raw

Quoted 5 lines · Steven Rostedt

The "print" in the trace_seq_printf() is the TP_printk() field of the TRACE_EVENT. I believe that there were some events (ext4?) that did things that required preemption disabled.

It seems that ext4 has no such events.
I find jbd2_dev_to_name() in the TP_printk() field of ext4's tracepoints. And it seems that jbd2_dev_to_name() requires preemption enabled and sleepable.

Maybe there were some events did things that required preemption disabled. But No document ensure TP_printk() preemption disabled, such events should be fixed, I think.

Steven Rostedt

maintainer

2010-06-04 03:03 UTC #3 lore raw

Quoted 8 lines · Lai Jiangshan

Quoted 5 lines · Steven Rostedt
The "print" in the trace_seq_printf() is the TP_printk() field of the TRACE_EVENT. I believe that there were some events (ext4?) that did things that required preemption disabled.

Quoted 7 lines

It seems that ext4 has no such events.
I find jbd2_dev_to_name() in the TP_printk() field of ext4's tracepoints. And it seems that jbd2_dev_to_name() requires preemption enabled and sleepable.
Maybe there were some events did things that required preemption disabled. But No document ensure TP_printk() preemption disabled, such events should be fixed, I think.

Well, I had a private email conversation with Ted last year where IIRC, adding the preempt disable would fix things.

I'd like to make sure Ted is OK with removing that before we do so.

Ted?

-- Steve

Lai Jiangshan

author

2010-06-07 07:50 UTC #4 lore raw

Quoted 15 lines · Steven Rostedt

Quoted 6 lines · Lai Jiangshan
Quoted 4 lines · Steven Rostedt
The "print" in the trace_seq_printf() is the TP_printk() field of the TRACE_EVENT. I believe that there were some events (ext4?) that did things that required preemption disabled.
Quoted 7 lines
It seems that ext4 has no such events.
I find jbd2_dev_to_name() in the TP_printk() field of ext4's tracepoints. And it seems that jbd2_dev_to_name() requires preemption enabled and sleepable.
Maybe there were some events did things that required preemption disabled. But No document ensure TP_printk() preemption disabled, such events should be fixed, I think.

Quoted 7 lines

Well, I had a private email conversation with Ted last year where IIRC, adding the preempt disable would fix things.
I'd like to make sure Ted is OK with removing that before we do so.
Ted?

Hi, Ted

Could you give some comments?
I'm waiting and will appreciate your help.

Thanx, Lai

Steven Rostedt

maintainer

2010-07-21 02:03 UTC #5 lore raw

Quoted 21 lines · Lai Jiangshan

Quoted 20 lines · Steven Rostedt
Quoted 6 lines · Lai Jiangshan
Quoted 4 lines · Steven Rostedt
The "print" in the trace_seq_printf() is the TP_printk() field of the TRACE_EVENT. I believe that there were some events (ext4?) that did things that required preemption disabled.
Quoted 7 lines
It seems that ext4 has no such events.
I find jbd2_dev_to_name() in the TP_printk() field of ext4's tracepoints. And it seems that jbd2_dev_to_name() requires preemption enabled and sleepable.
Maybe there were some events did things that required preemption disabled. But No document ensure TP_printk() preemption disabled, such events should be fixed, I think.
Well, I had a private email conversation with Ted last year where IIRC, adding the preempt disable would fix things.
I'd like to make sure Ted is OK with removing that before we do so.

Quoted 7 lines

Quoted 2 lines
Ted?
Hi, Ted
Could you give some comments?
I'm waiting and will appreciate your help.

Since I've not heard anything, I'm pulling this in for 2.6.36.

-- Steve

tip-bot for Lai Jiangshan

author

2010-07-23 12:10 UTC #6 lore raw

[tip:perf/core] tracing: Reduce latency and remove percpu trace_seq

In reply to Lai Jiangshan

Commit-ID:  bc289ae98b75d93228d24f521ef02a076e506e94
Gitweb:     http://git.kernel.org/tip/bc289ae98b75d93228d24f521ef02a076e506e94
Author:     Lai Jiangshan <[email protected]>
AuthorDate: Thu, 3 Jun 2010 18:26:24 +0800
Committer:  Steven Rostedt <[email protected]>
CommitDate: Tue, 20 Jul 2010 22:05:34 -0400

tracing: Reduce latency and remove percpu trace_seq

__print_flags() and __print_symbolic() use percpu trace_seq:

So we move this trace_seq to struct trace_iterator.

Signed-off-by Lai Jiangshan <[email protected]>

LKML-Reference: <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>

---
 include/linux/ftrace_event.h |    5 +++--
 include/trace/ftrace.h       |   12 +++---------
 kernel/trace/trace_output.c  |    3 ---
 3 files changed, 6 insertions(+), 14 deletions(-)

include/linux/ftrace_event.h +3 -2

index 2b7b139..02b8b24 100644
@@ -11,8 +11,6 @@ struct trace_array;
 struct tracer;
 struct dentry;
 
-DECLARE_PER_CPU(struct trace_seq, ftrace_event_seq);
-
 struct trace_print_flags {
 	unsigned long		mask;
 	const char		*name;

@@ -58,6 +56,9 @@ struct trace_iterator {
 	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
 	unsigned long		iter_flags;
 
+	/* trace_seq for __print_flags() and __print_symbolic() etc. */
+	struct trace_seq	tmp_seq;
+
 	/* The below is zeroed out in pipe_read */
 	struct trace_seq	seq;
 	struct trace_entry	*ent;

include/trace/ftrace.h +3 -9

index 55c1fd1..fb783d9 100644
@@ -145,7 +145,7 @@
  *	struct trace_seq *s = &iter->seq;
  *	struct ftrace_raw_<call> *field; <-- defined in stage 1
  *	struct trace_entry *entry;
- *	struct trace_seq *p;
+ *	struct trace_seq *p = &iter->tmp_seq;
  *	int ret;
  *
  *	entry = iter->ent;

@@ -157,12 +157,10 @@
  *
  *	field = (typeof(field))entry;
  *
- *	p = &get_cpu_var(ftrace_event_seq);
  *	trace_seq_init(p);
  *	ret = trace_seq_printf(s, "%s: ", <call>);
  *	if (ret)
  *		ret = trace_seq_printf(s, <TP_printk> "\n");
- *	put_cpu();
  *	if (!ret)
  *		return TRACE_TYPE_PARTIAL_LINE;
  *

@@ -216,7 +214,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##call *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	event = container_of(trace_event, struct ftrace_event_call,	\

@@ -231,12 +229,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", event->name);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

@@ -255,7 +251,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##template *field;				\
 	struct trace_entry *entry;					\
-	struct trace_seq *p;						\
+	struct trace_seq *p = &iter->tmp_seq;				\
 	int ret;							\
 									\
 	entry = iter->ent;						\

@@ -267,12 +263,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags,	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	p = &get_cpu_var(ftrace_event_seq);				\
 	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, "%s: ", #call);			\
 	if (ret)							\
 		ret = trace_seq_printf(s, print);			\
-	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\

kernel/trace/trace_output.c +0 -3

index 57c1b45..1ba64d3 100644
@@ -16,9 +16,6 @@
 
 DECLARE_RWSEM(trace_event_mutex);
 
-DEFINE_PER_CPU(struct trace_seq, ftrace_event_seq);
-EXPORT_PER_CPU_SYMBOL(ftrace_event_seq);
-
 static struct hlist_head event_hash[EVENT_HASHSIZE] __read_mostly;
 
 static int next_event_type = __TRACE_LAST_TYPE + 1;