[PATCH 00/16] [GIT PULL] updates for tip/tracing/ftrace

[PATCH 00/16] [GIT PULL] updates for tip/tracing/ftrace

[Steven Rostedt]

Ingo,

Please pull the latest tip/tracing/ftrace tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/ftrace


Frederic Weisbecker (1):
      tracing/core: bring back raw trace_printk for dynamic formats strings

Jason Baron (2):
      tracing: tracepoints for softirq entry/exit - add softirq-to-name array
      tracing: tracepoints for softirq entry/exit - tracepoints

KOSAKI Motohiro (1):
      tracing: Don't use tracing_record_cmdline() in workqueue tracer fix

Steven Rostedt (12):
      tracing: fix comments about trace buffer resizing
      tracing: protect ring_buffer_expanded with trace_types_lock
      ring-buffer: use CONFIG_HOTPLUG_CPU not CONFIG_HOTPLUG
      ring-buffer: remove unneeded get_online_cpus
      tracing: show that buffer size is not expanded
      tracing: make bprint event use the proper event id
      tracing: have event_trace_printk use static tracer
      tracing: export trace formats to user space
      tracing: fix stack tracer header
      tracing: explain why stack tracer is empty
      tracing: show event name in trace for TRACE_EVENT created events
      ring-buffer: document reader page design

----
 include/linux/interrupt.h            |    5 +
 include/linux/kernel.h               |   40 ++++++---
 include/trace/irq_event_types.h      |   12 +++
 kernel/softirq.c                     |   16 +++-
 kernel/trace/ring_buffer.c           |  168 +++++++++++++++++----------------
 kernel/trace/trace.c                 |  121 ++++++++++++++++++++++--
 kernel/trace/trace.h                 |   30 ++++++-
 kernel/trace/trace_event_types.h     |   11 ++-
 kernel/trace/trace_events.c          |   10 --
 kernel/trace/trace_events_stage_2.h  |    2 +-
 kernel/trace/trace_functions_graph.c |    6 +-
 kernel/trace/trace_mmiotrace.c       |    7 +-
 kernel/trace/trace_output.c          |   57 ++++++++++-
 kernel/trace/trace_printk.c          |  150 ++++++++++++++++++++++++++++--
 kernel/trace/trace_stack.c           |   19 ++++-
 kernel/trace/trace_workqueue.c       |   20 +++-
 16 files changed, 523 insertions(+), 151 deletions(-)
-- 

[PATCH 01/16] tracing: fix comments about trace buffer resizing

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-fix-comments-about-trace-buffer-resizing.patch --]
[-- Type: text/plain, Size: 1778 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: cleanup

Some of the comments about the trace buffer resizing is gobbledygook.
And I wonder why people question if I'm a native English speaker.

This patch makes the comments make a bit more sense.

Reported-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace.c |   19 ++++++++++++++++---
 1 files changed, 16 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index c3946a6..c61ee85 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2336,7 +2336,8 @@ static int tracing_resize_ring_buffer(unsigned long size)
 
 	/*
 	 * If kernel or user changes the size of the ring buffer
-	 * it get completed.
+	 * we use the size that was given, and we can forget about
+	 * expanding it later.
 	 */
 	ring_buffer_expanded = 1;
 
@@ -2351,8 +2352,20 @@ static int tracing_resize_ring_buffer(unsigned long size)
 		r = ring_buffer_resize(global_trace.buffer,
 				       global_trace.entries);
 		if (r < 0) {
-			/* AARGH! We are left with different
-			 * size max buffer!!!! */
+			/*
+			 * AARGH! We are left with different
+			 * size max buffer!!!!
+			 * The max buffer is our "snapshot" buffer.
+			 * When a tracer needs a snapshot (one of the
+			 * latency tracers), it swaps the max buffer
+			 * with the saved snap shot. We succeeded to
+			 * update the size of the main buffer, but failed to
+			 * update the size of the max buffer. But when we tried
+			 * to reset the main buffer to the original size, we
+			 * failed there too. This is very unlikely to
+			 * happen, but if it does, warn and kill all
+			 * tracing.
+			 */
 			WARN_ON(1);
 			tracing_disabled = 1;
 		}
-- 
1.6.1.3

-- 

[PATCH 02/16] tracing: protect ring_buffer_expanded with trace_types_lock

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-protect-ring_buffer_expanded-with-trace_typ.patch --]
[-- Type: text/plain, Size: 1334 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: prevent races with ring_buffer_expanded

This patch places the expanding of the tracing buffer under the
protection of the trace_types_lock mutex. It is highly unlikely
that there would be any contention, but better safe than sorry.

Reported-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace.c |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index c61ee85..04ab824 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2391,8 +2391,10 @@ int tracing_update_buffers(void)
 {
 	int ret = 0;
 
+	mutex_lock(&trace_types_lock);
 	if (!ring_buffer_expanded)
 		ret = tracing_resize_ring_buffer(trace_buf_size);
+	mutex_unlock(&trace_types_lock);
 
 	return ret;
 }
@@ -2412,6 +2414,8 @@ static int tracing_set_tracer(const char *buf)
 	struct tracer *t;
 	int ret = 0;
 
+	mutex_lock(&trace_types_lock);
+
 	if (!ring_buffer_expanded) {
 		ret = tracing_resize_ring_buffer(trace_buf_size);
 		if (ret < 0)
@@ -2419,7 +2423,6 @@ static int tracing_set_tracer(const char *buf)
 		ret = 0;
 	}
 
-	mutex_lock(&trace_types_lock);
 	for (t = trace_types; t; t = t->next) {
 		if (strcmp(t->name, buf) == 0)
 			break;
-- 
1.6.1.3

-- 

[PATCH 03/16] ring-buffer: use CONFIG_HOTPLUG_CPU not CONFIG_HOTPLUG

[Steven Rostedt]

[-- Attachment #1: 0003-ring-buffer-use-CONFIG_HOTPLUG_CPU-not-CONFIG_HOTPL.patch --]
[-- Type: text/plain, Size: 1780 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The hotplug code in the ring buffers is for use with CPU hotplug,
not generic hotplug.

Reported-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/ring_buffer.c |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index d07c288..035b56c 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -303,7 +303,7 @@ struct ring_buffer {
 
 	struct ring_buffer_per_cpu	**buffers;
 
-#ifdef CONFIG_HOTPLUG
+#ifdef CONFIG_HOTPLUG_CPU
 	struct notifier_block		cpu_notify;
 #endif
 };
@@ -464,7 +464,7 @@ static void rb_free_cpu_buffer(struct ring_buffer_per_cpu *cpu_buffer)
  */
 extern int ring_buffer_page_too_big(void);
 
-#ifdef CONFIG_HOTPLUG
+#ifdef CONFIG_HOTPLUG_CPU
 static int __cpuinit rb_cpu_notify(struct notifier_block *self,
 				   unsigned long action, void *hcpu);
 #endif
@@ -523,7 +523,7 @@ struct ring_buffer *ring_buffer_alloc(unsigned long size, unsigned flags)
 			goto fail_free_buffers;
 	}
 
-#ifdef CONFIG_HOTPLUG
+#ifdef CONFIG_HOTPLUG_CPU
 	buffer->cpu_notify.notifier_call = rb_cpu_notify;
 	buffer->cpu_notify.priority = 0;
 	register_cpu_notifier(&buffer->cpu_notify);
@@ -562,7 +562,7 @@ ring_buffer_free(struct ring_buffer *buffer)
 
 	get_online_cpus();
 
-#ifdef CONFIG_HOTPLUG
+#ifdef CONFIG_HOTPLUG_CPU
 	unregister_cpu_notifier(&buffer->cpu_notify);
 #endif
 
@@ -2757,7 +2757,7 @@ static __init int rb_init_debugfs(void)
 
 fs_initcall(rb_init_debugfs);
 
-#ifdef CONFIG_HOTPLUG
+#ifdef CONFIG_HOTPLUG_CPU
 static int __cpuinit rb_cpu_notify(struct notifier_block *self,
 				   unsigned long action, void *hcpu)
 {
-- 
1.6.1.3

-- 

[PATCH 04/16] ring-buffer: remove unneeded get_online_cpus

[Steven Rostedt]

[-- Attachment #1: 0004-ring-buffer-remove-unneeded-get_online_cpus.patch --]
[-- Type: text/plain, Size: 7683 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: speed up and remove possible races

The get_online_cpus was added to the ring buffer because the original
design would free the ring buffer on a CPU that was being taken
off line. The final design kept the ring buffer around even when the
CPU was taken off line. This is to allow a user to still read the
information on that ring buffer.

Most of the get_online_cpus are no longer needed since the ring buffer will
not disappear from the use cases.

Reported-by: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/ring_buffer.c |   90 +++++++-------------------------------------
 1 files changed, 14 insertions(+), 76 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 035b56c..2c36be9 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -1561,15 +1561,11 @@ void ring_buffer_record_disable_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return;
 
 	cpu_buffer = buffer->buffers[cpu];
 	atomic_inc(&cpu_buffer->record_disabled);
- out:
-	put_online_cpus();
 }
 EXPORT_SYMBOL_GPL(ring_buffer_record_disable_cpu);
 
@@ -1585,15 +1581,11 @@ void ring_buffer_record_enable_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return;
 
 	cpu_buffer = buffer->buffers[cpu];
 	atomic_dec(&cpu_buffer->record_disabled);
- out:
-	put_online_cpus();
 }
 EXPORT_SYMBOL_GPL(ring_buffer_record_enable_cpu);
 
@@ -1605,17 +1597,13 @@ EXPORT_SYMBOL_GPL(ring_buffer_record_enable_cpu);
 unsigned long ring_buffer_entries_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
-	unsigned long ret = 0;
-
-	get_online_cpus();
+	unsigned long ret;
 
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return 0;
 
 	cpu_buffer = buffer->buffers[cpu];
 	ret = cpu_buffer->entries;
- out:
-	put_online_cpus();
 
 	return ret;
 }
@@ -1629,17 +1617,13 @@ EXPORT_SYMBOL_GPL(ring_buffer_entries_cpu);
 unsigned long ring_buffer_overrun_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
-	unsigned long ret = 0;
-
-	get_online_cpus();
+	unsigned long ret;
 
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return 0;
 
 	cpu_buffer = buffer->buffers[cpu];
 	ret = cpu_buffer->overrun;
- out:
-	put_online_cpus();
 
 	return ret;
 }
@@ -1658,16 +1642,12 @@ unsigned long ring_buffer_entries(struct ring_buffer *buffer)
 	unsigned long entries = 0;
 	int cpu;
 
-	get_online_cpus();
-
 	/* if you care about this being correct, lock the buffer */
 	for_each_buffer_cpu(buffer, cpu) {
 		cpu_buffer = buffer->buffers[cpu];
 		entries += cpu_buffer->entries;
 	}
 
-	put_online_cpus();
-
 	return entries;
 }
 EXPORT_SYMBOL_GPL(ring_buffer_entries);
@@ -1685,16 +1665,12 @@ unsigned long ring_buffer_overruns(struct ring_buffer *buffer)
 	unsigned long overruns = 0;
 	int cpu;
 
-	get_online_cpus();
-
 	/* if you care about this being correct, lock the buffer */
 	for_each_buffer_cpu(buffer, cpu) {
 		cpu_buffer = buffer->buffers[cpu];
 		overruns += cpu_buffer->overrun;
 	}
 
-	put_online_cpus();
-
 	return overruns;
 }
 EXPORT_SYMBOL_GPL(ring_buffer_overruns);
@@ -2093,21 +2069,16 @@ struct ring_buffer_event *
 ring_buffer_peek(struct ring_buffer *buffer, int cpu, u64 *ts)
 {
 	struct ring_buffer_per_cpu *cpu_buffer = buffer->buffers[cpu];
-	struct ring_buffer_event *event = NULL;
+	struct ring_buffer_event *event;
 	unsigned long flags;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return NULL;
 
 	spin_lock_irqsave(&cpu_buffer->reader_lock, flags);
 	event = rb_buffer_peek(buffer, cpu, ts);
 	spin_unlock_irqrestore(&cpu_buffer->reader_lock, flags);
 
- out:
-	put_online_cpus();
-
 	return event;
 }
 
@@ -2189,17 +2160,15 @@ struct ring_buffer_iter *
 ring_buffer_read_start(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
-	struct ring_buffer_iter *iter = NULL;
+	struct ring_buffer_iter *iter;
 	unsigned long flags;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return NULL;
 
 	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
 	if (!iter)
-		goto out;
+		return NULL;
 
 	cpu_buffer = buffer->buffers[cpu];
 
@@ -2214,9 +2183,6 @@ ring_buffer_read_start(struct ring_buffer *buffer, int cpu)
 	__raw_spin_unlock(&cpu_buffer->lock);
 	spin_unlock_irqrestore(&cpu_buffer->reader_lock, flags);
 
- out:
-	put_online_cpus();
-
 	return iter;
 }
 EXPORT_SYMBOL_GPL(ring_buffer_read_start);
@@ -2309,13 +2275,9 @@ void ring_buffer_reset_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer = buffer->buffers[cpu];
 	unsigned long flags;
-	int resched;
-
-	/* Can't use get_online_cpus because this can be in atomic */
-	resched = ftrace_preempt_disable();
 
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return;
 
 	spin_lock_irqsave(&cpu_buffer->reader_lock, flags);
 
@@ -2326,8 +2288,6 @@ void ring_buffer_reset_cpu(struct ring_buffer *buffer, int cpu)
 	__raw_spin_unlock(&cpu_buffer->lock);
 
 	spin_unlock_irqrestore(&cpu_buffer->reader_lock, flags);
- out:
-	ftrace_preempt_enable(resched);
 }
 EXPORT_SYMBOL_GPL(ring_buffer_reset_cpu);
 
@@ -2337,16 +2297,10 @@ EXPORT_SYMBOL_GPL(ring_buffer_reset_cpu);
  */
 void ring_buffer_reset(struct ring_buffer *buffer)
 {
-	int resched;
 	int cpu;
 
-	/* Can't use get_online_cpus because this can be in atomic */
-	resched = ftrace_preempt_disable();
-
 	for_each_buffer_cpu(buffer, cpu)
 		ring_buffer_reset_cpu(buffer, cpu);
-
-	ftrace_preempt_enable(resched);
 }
 EXPORT_SYMBOL_GPL(ring_buffer_reset);
 
@@ -2359,8 +2313,6 @@ int ring_buffer_empty(struct ring_buffer *buffer)
 	struct ring_buffer_per_cpu *cpu_buffer;
 	int cpu;
 
-	get_online_cpus();
-
 	/* yes this is racy, but if you don't like the race, lock the buffer */
 	for_each_buffer_cpu(buffer, cpu) {
 		cpu_buffer = buffer->buffers[cpu];
@@ -2368,8 +2320,6 @@ int ring_buffer_empty(struct ring_buffer *buffer)
 			return 0;
 	}
 
-	put_online_cpus();
-
 	return 1;
 }
 EXPORT_SYMBOL_GPL(ring_buffer_empty);
@@ -2382,18 +2332,14 @@ EXPORT_SYMBOL_GPL(ring_buffer_empty);
 int ring_buffer_empty_cpu(struct ring_buffer *buffer, int cpu)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
-	int ret = 1;
-
-	get_online_cpus();
+	int ret;
 
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
-		goto out;
+		return 1;
 
 	cpu_buffer = buffer->buffers[cpu];
 	ret = rb_per_cpu_empty(cpu_buffer);
 
- out:
-	put_online_cpus();
 
 	return ret;
 }
@@ -2416,8 +2362,6 @@ int ring_buffer_swap_cpu(struct ring_buffer *buffer_a,
 	struct ring_buffer_per_cpu *cpu_buffer_b;
 	int ret = -EINVAL;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer_a->cpumask) ||
 	    !cpumask_test_cpu(cpu, buffer_b->cpumask))
 		goto out;
@@ -2466,8 +2410,6 @@ int ring_buffer_swap_cpu(struct ring_buffer *buffer_a,
 
 	ret = 0;
 out:
-	put_online_cpus();
-
 	return ret;
 }
 EXPORT_SYMBOL_GPL(ring_buffer_swap_cpu);
@@ -2583,8 +2525,6 @@ int ring_buffer_read_page(struct ring_buffer *buffer,
 	u64 save_timestamp;
 	int ret = -1;
 
-	get_online_cpus();
-
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
 		goto out;
 
@@ -2681,8 +2621,6 @@ int ring_buffer_read_page(struct ring_buffer *buffer,
 	spin_unlock_irqrestore(&cpu_buffer->reader_lock, flags);
 
  out:
-	put_online_cpus();
-
 	return ret;
 }
 
-- 
1.6.1.3

-- 

[PATCH 05/16] tracing: show that buffer size is not expanded

[Steven Rostedt]

[-- Attachment #1: 0005-tracing-show-that-buffer-size-is-not-expanded.patch --]
[-- Type: text/plain, Size: 1555 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: do not confuse user on small trace buffer sizes

When the system boots up, the trace buffer is small to conserve memory.
It is only two pages per online CPU. When the tracer is used, it expands
to the default value.

This can confuse the user if they look at the buffer size and see only
7, but then later they see 1408.

 # cat /debug/tracing/buffer_size_kb
7

 # echo sched_switch > /debug/tracing/current_tracer

 # cat /debug/tracing/buffer_size_kb
1408

This patch tries to help remove this confustion by showing that the
buffer has not been expanded.

 # cat /debug/tracing/buffer_size_kb
7 (expanded: 1408)

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 04ab824..62a63b2 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2948,10 +2948,18 @@ tracing_entries_read(struct file *filp, char __user *ubuf,
 		     size_t cnt, loff_t *ppos)
 {
 	struct trace_array *tr = filp->private_data;
-	char buf[64];
+	char buf[96];
 	int r;
 
-	r = sprintf(buf, "%lu\n", tr->entries >> 10);
+	mutex_lock(&trace_types_lock);
+	if (!ring_buffer_expanded)
+		r = sprintf(buf, "%lu (expanded: %lu)\n",
+			    tr->entries >> 10,
+			    trace_buf_size >> 10);
+	else
+		r = sprintf(buf, "%lu\n", tr->entries >> 10);
+	mutex_unlock(&trace_types_lock);
+
 	return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
 }
 
-- 
1.6.1.3

-- 

Re: [PATCH 05/16] tracing: show that buffer size is not expanded

[KOSAKI Motohiro]

> From: Steven Rostedt <srostedt@redhat.com>
> 
> Impact: do not confuse user on small trace buffer sizes
> 
> When the system boots up, the trace buffer is small to conserve memory.
> It is only two pages per online CPU. When the tracer is used, it expands
> to the default value.
> 
> This can confuse the user if they look at the buffer size and see only
> 7, but then later they see 1408.
> 
>  # cat /debug/tracing/buffer_size_kb
> 7
> 
>  # echo sched_switch > /debug/tracing/current_tracer
> 
>  # cat /debug/tracing/buffer_size_kb
> 1408
> 
> This patch tries to help remove this confustion by showing that the
> buffer has not been expanded.
> 
>  # cat /debug/tracing/buffer_size_kb
> 7 (expanded: 1408)

Hi,

I have one question.
Why souldn't use following output?

sprintf(buf, "%lu\n", trace_buf_size >> 10);


My point is:
  - pure number output can hadle easily.
  - nobody need to know internal memory saving logic.

Re: [PATCH 05/16] tracing: show that buffer size is not expanded

[Steven Rostedt]

On Fri, 13 Mar 2009, KOSAKI Motohiro wrote:

> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > Impact: do not confuse user on small trace buffer sizes
> > 
> > When the system boots up, the trace buffer is small to conserve memory.
> > It is only two pages per online CPU. When the tracer is used, it expands
> > to the default value.
> > 
> > This can confuse the user if they look at the buffer size and see only
> > 7, but then later they see 1408.
> > 
> >  # cat /debug/tracing/buffer_size_kb
> > 7
> > 
> >  # echo sched_switch > /debug/tracing/current_tracer
> > 
> >  # cat /debug/tracing/buffer_size_kb
> > 1408
> > 
> > This patch tries to help remove this confustion by showing that the
> > buffer has not been expanded.
> > 
> >  # cat /debug/tracing/buffer_size_kb
> > 7 (expanded: 1408)
> 
> Hi,
> 
> I have one question.
> Why souldn't use following output?
> 
> sprintf(buf, "%lu\n", trace_buf_size >> 10);
> 
> 
> My point is:
>   - pure number output can hadle easily.
>   - nobody need to know internal memory saving logic.

My answer to the second point is: "I do" ;-)

I like to know the real buffer size. That '7' comes from the ring buffer 
size directly. If something is going wrong, I do not want to hide the fact 
that the ring buffer size is not what I expect it to be. Lets say someone 
modifies the code, and we miss expanding the buffer. It will be very hard 
to debug why we are getting a small trace. But if we see that the buffer 
has not been expanded, we know exactly what is wrong.

-- Steve

Re: [PATCH 05/16] tracing: show that buffer size is not expanded

[KOSAKI Motohiro]

> > >  # cat /debug/tracing/buffer_size_kb
> > > 7 (expanded: 1408)
> > 
> > Hi,
> > 
> > I have one question.
> > Why souldn't use following output?
> > 
> > sprintf(buf, "%lu\n", trace_buf_size >> 10);
> > 
> > 
> > My point is:
> >   - pure number output can hadle easily.
> >   - nobody need to know internal memory saving logic.
> 
> My answer to the second point is: "I do" ;-)
> 
> I like to know the real buffer size. That '7' comes from the ring buffer 
> size directly. If something is going wrong, I do not want to hide the fact 
> that the ring buffer size is not what I expect it to be. Lets say someone 
> modifies the code, and we miss expanding the buffer. It will be very hard 
> to debug why we are getting a small trace. But if we see that the buffer 
> has not been expanded, we know exactly what is wrong.

ok. understanding.
please ignore my last mail.

Thanks!

[PATCH 06/16] tracing/core: bring back raw trace_printk for dynamic formats strings

[Steven Rostedt]

[-- Attachment #1: 0006-tracing-core-bring-back-raw-trace_printk-for-dynami.patch --]
[-- Type: text/plain, Size: 16778 bytes --]

From: Frederic Weisbecker <fweisbec@gmail.com>

Impact: fix callsites with dynamic format strings

Since its new binary implementation, trace_printk() internally uses static
containers for the format strings on each callsites. But the value is
assigned once at build time, which means that it can't take dynamic
formats.

So this patch unearthes the raw trace_printk implementation for the callers
that will need trace_printk to be able to carry these dynamic format
strings. The trace_printk() macro will use the appropriate implementation
for each callsite. Most of the time however, the binary implementation will
still be used.

The other impact of this patch is that mmiotrace_printk() will use the old
implementation because it calls the low level trace_vprintk and we can't
guess here whether the format passed in it is dynamic or not.

Some parts of this patch have been written by Steven Rostedt (most notably
the part that chooses the appropriate implementation for each callsites).

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/kernel.h               |   40 +++++++++++-----
 kernel/trace/trace.c                 |   85 ++++++++++++++++++++++++++++++++--
 kernel/trace/trace.h                 |   13 +++++-
 kernel/trace/trace_event_types.h     |   11 ++++-
 kernel/trace/trace_functions_graph.c |    6 +-
 kernel/trace/trace_mmiotrace.c       |    7 +--
 kernel/trace/trace_output.c          |   57 ++++++++++++++++++++--
 kernel/trace/trace_printk.c          |   33 +++++++++++--
 8 files changed, 213 insertions(+), 39 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 7742798..1daca3b 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -452,32 +452,46 @@ do {									\
 
 #define trace_printk(fmt, args...)					\
 do {									\
-	static const char *trace_printk_fmt				\
-	__attribute__((section("__trace_printk_fmt")));			\
-									\
-	if (!trace_printk_fmt)						\
-		trace_printk_fmt = fmt;					\
-									\
 	__trace_printk_check_format(fmt, ##args);			\
-	__trace_printk(_THIS_IP_, trace_printk_fmt, ##args);		\
+	if (__builtin_constant_p(fmt)) {				\
+		static const char *trace_printk_fmt			\
+		  __attribute__((section("__trace_printk_fmt"))) =	\
+			__builtin_constant_p(fmt) ? fmt : NULL;		\
+									\
+		__trace_bprintk(_THIS_IP_, trace_printk_fmt, ##args);	\
+	} else								\
+		__trace_printk(_THIS_IP_, fmt, ##args);		\
 } while (0)
 
 extern int
+__trace_bprintk(unsigned long ip, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+
+extern int
 __trace_printk(unsigned long ip, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
 
+/*
+ * The double __builtin_constant_p is because gcc will give us an error
+ * if we try to allocate the static variable to fmt if it is not a
+ * constant. Even with the outer if statement.
+ */
 #define ftrace_vprintk(fmt, vargs)					\
 do {									\
-	static const char *trace_printk_fmt				\
-	__attribute__((section("__trace_printk_fmt")));			\
-									\
-	if (!trace_printk_fmt)						\
-		trace_printk_fmt = fmt;					\
+	if (__builtin_constant_p(fmt)) {				\
+		static const char *trace_printk_fmt			\
+		  __attribute__((section("__trace_printk_fmt"))) =	\
+			__builtin_constant_p(fmt) ? fmt : NULL;		\
 									\
-	__ftrace_vprintk(_THIS_IP_, trace_printk_fmt, vargs);		\
+		__ftrace_vbprintk(_THIS_IP_, trace_printk_fmt, vargs);	\
+	} else								\
+		__ftrace_vprintk(_THIS_IP_, fmt, vargs);		\
 } while (0)
 
 extern int
+__ftrace_vbprintk(unsigned long ip, const char *fmt, va_list ap);
+
+extern int
 __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap);
 
 extern void ftrace_dump(void);
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 62a63b2..dbb077d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1179,10 +1179,10 @@ void trace_graph_return(struct ftrace_graph_ret *trace)
 
 
 /**
- * trace_vprintk - write binary msg to tracing buffer
+ * trace_vbprintk - write binary msg to tracing buffer
  *
  */
-int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
+int trace_vbprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 {
 	static raw_spinlock_t trace_buf_lock =
 		(raw_spinlock_t)__RAW_SPIN_LOCK_UNLOCKED;
@@ -1191,7 +1191,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 	struct ring_buffer_event *event;
 	struct trace_array *tr = &global_trace;
 	struct trace_array_cpu *data;
-	struct print_entry *entry;
+	struct bprint_entry *entry;
 	unsigned long flags;
 	int resched;
 	int cpu, len = 0, size, pc;
@@ -1219,7 +1219,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 		goto out_unlock;
 
 	size = sizeof(*entry) + sizeof(u32) * len;
-	event = trace_buffer_lock_reserve(tr, TRACE_PRINT, size, flags, pc);
+	event = trace_buffer_lock_reserve(tr, TRACE_BPRINT, size, flags, pc);
 	if (!event)
 		goto out_unlock;
 	entry = ring_buffer_event_data(event);
@@ -1240,6 +1240,60 @@ out:
 
 	return len;
 }
+EXPORT_SYMBOL_GPL(trace_vbprintk);
+
+int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
+{
+	static raw_spinlock_t trace_buf_lock = __RAW_SPIN_LOCK_UNLOCKED;
+	static char trace_buf[TRACE_BUF_SIZE];
+
+	struct ring_buffer_event *event;
+	struct trace_array *tr = &global_trace;
+	struct trace_array_cpu *data;
+	int cpu, len = 0, size, pc;
+	struct print_entry *entry;
+	unsigned long irq_flags;
+
+	if (tracing_disabled || tracing_selftest_running)
+		return 0;
+
+	pc = preempt_count();
+	preempt_disable_notrace();
+	cpu = raw_smp_processor_id();
+	data = tr->data[cpu];
+
+	if (unlikely(atomic_read(&data->disabled)))
+		goto out;
+
+	pause_graph_tracing();
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&trace_buf_lock);
+	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
+
+	len = min(len, TRACE_BUF_SIZE-1);
+	trace_buf[len] = 0;
+
+	size = sizeof(*entry) + len + 1;
+	event = trace_buffer_lock_reserve(tr, TRACE_PRINT, size, irq_flags, pc);
+	if (!event)
+		goto out_unlock;
+	entry = ring_buffer_event_data(event);
+	entry->ip			= ip;
+	entry->depth			= depth;
+
+	memcpy(&entry->buf, trace_buf, len);
+	entry->buf[len] = 0;
+	ring_buffer_unlock_commit(tr->buffer, event);
+
+ out_unlock:
+	__raw_spin_unlock(&trace_buf_lock);
+	raw_local_irq_restore(irq_flags);
+	unpause_graph_tracing();
+ out:
+	preempt_enable_notrace();
+
+	return len;
+}
 EXPORT_SYMBOL_GPL(trace_vprintk);
 
 enum trace_file_type {
@@ -1628,6 +1682,22 @@ static enum print_line_t print_hex_fmt(struct trace_iterator *iter)
 	return TRACE_TYPE_HANDLED;
 }
 
+static enum print_line_t print_bprintk_msg_only(struct trace_iterator *iter)
+{
+	struct trace_seq *s = &iter->seq;
+	struct trace_entry *entry = iter->ent;
+	struct bprint_entry *field;
+	int ret;
+
+	trace_assign_type(field, entry);
+
+	ret = trace_seq_bprintf(s, field->fmt, field->buf);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	return TRACE_TYPE_HANDLED;
+}
+
 static enum print_line_t print_printk_msg_only(struct trace_iterator *iter)
 {
 	struct trace_seq *s = &iter->seq;
@@ -1637,7 +1707,7 @@ static enum print_line_t print_printk_msg_only(struct trace_iterator *iter)
 
 	trace_assign_type(field, entry);
 
-	ret = trace_seq_bprintf(s, field->fmt, field->buf);
+	ret = trace_seq_printf(s, "%s", field->buf);
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
@@ -1702,6 +1772,11 @@ static enum print_line_t print_trace_line(struct trace_iterator *iter)
 			return ret;
 	}
 
+	if (iter->ent->type == TRACE_BPRINT &&
+			trace_flags & TRACE_ITER_PRINTK &&
+			trace_flags & TRACE_ITER_PRINTK_MSGONLY)
+		return print_bprintk_msg_only(iter);
+
 	if (iter->ent->type == TRACE_PRINT &&
 			trace_flags & TRACE_ITER_PRINTK &&
 			trace_flags & TRACE_ITER_PRINTK_MSGONLY)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 336324d..cede1ab 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -20,6 +20,7 @@ enum trace_type {
 	TRACE_WAKE,
 	TRACE_STACK,
 	TRACE_PRINT,
+	TRACE_BPRINT,
 	TRACE_SPECIAL,
 	TRACE_MMIO_RW,
 	TRACE_MMIO_MAP,
@@ -117,7 +118,7 @@ struct userstack_entry {
 /*
  * trace_printk entry:
  */
-struct print_entry {
+struct bprint_entry {
 	struct trace_entry	ent;
 	unsigned long		ip;
 	int			depth;
@@ -125,6 +126,13 @@ struct print_entry {
 	u32			buf[];
 };
 
+struct print_entry {
+	struct trace_entry	ent;
+	unsigned long		ip;
+	int			depth;
+	char			buf[];
+};
+
 #define TRACE_OLD_SIZE		88
 
 struct trace_field_cont {
@@ -286,6 +294,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct stack_entry, TRACE_STACK);	\
 		IF_ASSIGN(var, ent, struct userstack_entry, TRACE_USER_STACK);\
 		IF_ASSIGN(var, ent, struct print_entry, TRACE_PRINT);	\
+		IF_ASSIGN(var, ent, struct bprint_entry, TRACE_BPRINT);	\
 		IF_ASSIGN(var, ent, struct special_entry, 0);		\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\
 			  TRACE_MMIO_RW);				\
@@ -570,6 +579,8 @@ extern int trace_selftest_startup_branch(struct tracer *trace,
 extern void *head_page(struct trace_array_cpu *data);
 extern long ns2usecs(cycle_t nsec);
 extern int
+trace_vbprintk(unsigned long ip, int depth, const char *fmt, va_list args);
+extern int
 trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args);
 
 extern unsigned long trace_flags;
diff --git a/kernel/trace/trace_event_types.h b/kernel/trace/trace_event_types.h
index 5cca4c9..d0907d7 100644
--- a/kernel/trace/trace_event_types.h
+++ b/kernel/trace/trace_event_types.h
@@ -102,7 +102,7 @@ TRACE_EVENT_FORMAT(user_stack, TRACE_USER_STACK, userstack_entry, ignore,
 		 "\t=> (%08lx)\n\t=> (%08lx)\n\t=> (%08lx)\n\t=> (%08lx)\n")
 );
 
-TRACE_EVENT_FORMAT(print, TRACE_PRINT, print_entry, ignore,
+TRACE_EVENT_FORMAT(bprint, TRACE_PRINT, bprint_entry, ignore,
 	TRACE_STRUCT(
 		TRACE_FIELD(unsigned long, ip, ip)
 		TRACE_FIELD(unsigned int, depth, depth)
@@ -112,6 +112,15 @@ TRACE_EVENT_FORMAT(print, TRACE_PRINT, print_entry, ignore,
 	TP_RAW_FMT("%08lx (%d) fmt:%p %s")
 );
 
+TRACE_EVENT_FORMAT(print, TRACE_PRINT, print_entry, ignore,
+	TRACE_STRUCT(
+		TRACE_FIELD(unsigned long, ip, ip)
+		TRACE_FIELD(unsigned int, depth, depth)
+		TRACE_FIELD_ZERO_CHAR(buf)
+	),
+	TP_RAW_FMT("%08lx (%d) fmt:%p %s")
+);
+
 TRACE_EVENT_FORMAT(branch, TRACE_BRANCH, trace_branch, ignore,
 	TRACE_STRUCT(
 		TRACE_FIELD(unsigned int, line, line)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 8566c14..4c38860 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -684,7 +684,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 }
 
 static enum print_line_t
-print_graph_comment(struct print_entry *trace, struct trace_seq *s,
+print_graph_comment(struct bprint_entry *trace, struct trace_seq *s,
 		   struct trace_entry *ent, struct trace_iterator *iter)
 {
 	int i;
@@ -781,8 +781,8 @@ print_graph_function(struct trace_iterator *iter)
 		trace_assign_type(field, entry);
 		return print_graph_return(&field->ret, s, entry, iter);
 	}
-	case TRACE_PRINT: {
-		struct print_entry *field;
+	case TRACE_BPRINT: {
+		struct bprint_entry *field;
 		trace_assign_type(field, entry);
 		return print_graph_comment(field, s, entry, iter);
 	}
diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 23e346a..f095916 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -254,6 +254,7 @@ static enum print_line_t mmio_print_mark(struct trace_iterator *iter)
 {
 	struct trace_entry *entry = iter->ent;
 	struct print_entry *print = (struct print_entry *)entry;
+	const char *msg		= print->buf;
 	struct trace_seq *s	= &iter->seq;
 	unsigned long long t	= ns2usecs(iter->ts);
 	unsigned long usec_rem	= do_div(t, USEC_PER_SEC);
@@ -261,11 +262,7 @@ static enum print_line_t mmio_print_mark(struct trace_iterator *iter)
 	int ret;
 
 	/* The trailing newline must be in the message. */
-	ret = trace_seq_printf(s, "MARK %u.%06lu ", secs, usec_rem);
-	if (!ret)
-		return TRACE_TYPE_PARTIAL_LINE;
-
-	ret = trace_seq_bprintf(s, print->fmt, print->buf);
+	ret = trace_seq_printf(s, "MARK %u.%06lu %s", secs, usec_rem, msg);
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 491832a..ea9d3b4 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -832,13 +832,13 @@ static struct trace_event trace_user_stack_event = {
 	.binary		= trace_special_bin,
 };
 
-/* TRACE_PRINT */
+/* TRACE_BPRINT */
 static enum print_line_t
-trace_print_print(struct trace_iterator *iter, int flags)
+trace_bprint_print(struct trace_iterator *iter, int flags)
 {
 	struct trace_entry *entry = iter->ent;
 	struct trace_seq *s = &iter->seq;
-	struct print_entry *field;
+	struct bprint_entry *field;
 
 	trace_assign_type(field, entry);
 
@@ -858,9 +858,10 @@ trace_print_print(struct trace_iterator *iter, int flags)
 }
 
 
-static enum print_line_t trace_print_raw(struct trace_iterator *iter, int flags)
+static enum print_line_t
+trace_bprint_raw(struct trace_iterator *iter, int flags)
 {
-	struct print_entry *field;
+	struct bprint_entry *field;
 	struct trace_seq *s = &iter->seq;
 
 	trace_assign_type(field, iter->ent);
@@ -878,12 +879,55 @@ static enum print_line_t trace_print_raw(struct trace_iterator *iter, int flags)
 }
 
 
+static struct trace_event trace_bprint_event = {
+	.type		= TRACE_BPRINT,
+	.trace		= trace_bprint_print,
+	.raw		= trace_bprint_raw,
+};
+
+/* TRACE_PRINT */
+static enum print_line_t trace_print_print(struct trace_iterator *iter,
+					   int flags)
+{
+	struct print_entry *field;
+	struct trace_seq *s = &iter->seq;
+
+	trace_assign_type(field, iter->ent);
+
+	if (!seq_print_ip_sym(s, field->ip, flags))
+		goto partial;
+
+	if (!trace_seq_printf(s, ": %s", field->buf))
+		goto partial;
+
+	return TRACE_TYPE_HANDLED;
+
+ partial:
+	return TRACE_TYPE_PARTIAL_LINE;
+}
+
+static enum print_line_t trace_print_raw(struct trace_iterator *iter, int flags)
+{
+	struct print_entry *field;
+
+	trace_assign_type(field, iter->ent);
+
+	if (!trace_seq_printf(&iter->seq, "# %lx %s", field->ip, field->buf))
+		goto partial;
+
+	return TRACE_TYPE_HANDLED;
+
+ partial:
+	return TRACE_TYPE_PARTIAL_LINE;
+}
+
 static struct trace_event trace_print_event = {
-	.type		= TRACE_PRINT,
+	.type	 	= TRACE_PRINT,
 	.trace		= trace_print_print,
 	.raw		= trace_print_raw,
 };
 
+
 static struct trace_event *events[] __initdata = {
 	&trace_fn_event,
 	&trace_ctx_event,
@@ -891,6 +935,7 @@ static struct trace_event *events[] __initdata = {
 	&trace_special_event,
 	&trace_stack_event,
 	&trace_user_stack_event,
+	&trace_bprint_event,
 	&trace_print_event,
 	NULL
 };
diff --git a/kernel/trace/trace_printk.c b/kernel/trace/trace_printk.c
index a50aea2..f307a11 100644
--- a/kernel/trace/trace_printk.c
+++ b/kernel/trace/trace_printk.c
@@ -99,7 +99,7 @@ struct notifier_block module_trace_bprintk_format_nb = {
 	.notifier_call = module_trace_bprintk_format_notify,
 };
 
-int __trace_printk(unsigned long ip, const char *fmt, ...)
+int __trace_bprintk(unsigned long ip, const char *fmt, ...)
  {
 	int ret;
 	va_list ap;
@@ -111,13 +111,13 @@ int __trace_printk(unsigned long ip, const char *fmt, ...)
 		return 0;
 
 	va_start(ap, fmt);
-	ret = trace_vprintk(ip, task_curr_ret_stack(current), fmt, ap);
+	ret = trace_vbprintk(ip, task_curr_ret_stack(current), fmt, ap);
 	va_end(ap);
 	return ret;
 }
-EXPORT_SYMBOL_GPL(__trace_printk);
+EXPORT_SYMBOL_GPL(__trace_bprintk);
 
-int __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap)
+int __ftrace_vbprintk(unsigned long ip, const char *fmt, va_list ap)
  {
 	if (unlikely(!fmt))
 		return 0;
@@ -125,11 +125,34 @@ int __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap)
 	if (!(trace_flags & TRACE_ITER_PRINTK))
 		return 0;
 
+	return trace_vbprintk(ip, task_curr_ret_stack(current), fmt, ap);
+}
+EXPORT_SYMBOL_GPL(__ftrace_vbprintk);
+
+int __trace_printk(unsigned long ip, const char *fmt, ...)
+{
+	int ret;
+	va_list ap;
+
+	if (!(trace_flags & TRACE_ITER_PRINTK))
+		return 0;
+
+	va_start(ap, fmt);
+	ret = trace_vprintk(ip, task_curr_ret_stack(current), fmt, ap);
+	va_end(ap);
+	return ret;
+}
+EXPORT_SYMBOL_GPL(__trace_printk);
+
+int __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap)
+{
+	if (!(trace_flags & TRACE_ITER_PRINTK))
+		return 0;
+
 	return trace_vprintk(ip, task_curr_ret_stack(current), fmt, ap);
 }
 EXPORT_SYMBOL_GPL(__ftrace_vprintk);
 
-
 static __init int init_trace_printk(void)
 {
 	return register_module_notifier(&module_trace_bprintk_format_nb);
-- 
1.6.1.3

-- 

[PATCH 07/16] tracing: make bprint event use the proper event id

[Steven Rostedt]

[-- Attachment #1: 0007-tracing-make-bprint-event-use-the-proper-event-id.patch --]
[-- Type: text/plain, Size: 861 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The bprint record is using TRACE_PRINT when it should be TRACE_BPRINT.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_event_types.h |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_event_types.h b/kernel/trace/trace_event_types.h
index d0907d7..0199150 100644
--- a/kernel/trace/trace_event_types.h
+++ b/kernel/trace/trace_event_types.h
@@ -102,7 +102,7 @@ TRACE_EVENT_FORMAT(user_stack, TRACE_USER_STACK, userstack_entry, ignore,
 		 "\t=> (%08lx)\n\t=> (%08lx)\n\t=> (%08lx)\n\t=> (%08lx)\n")
 );
 
-TRACE_EVENT_FORMAT(bprint, TRACE_PRINT, bprint_entry, ignore,
+TRACE_EVENT_FORMAT(bprint, TRACE_BPRINT, bprint_entry, ignore,
 	TRACE_STRUCT(
 		TRACE_FIELD(unsigned long, ip, ip)
 		TRACE_FIELD(unsigned int, depth, depth)
-- 
1.6.1.3

-- 

[PATCH 08/16] tracing: have event_trace_printk use static tracer

[Steven Rostedt]

[-- Attachment #1: 0008-tracing-have-event_trace_printk-use-static-tracer.patch --]
[-- Type: text/plain, Size: 2194 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Impact: speed up on event tracing

The event_trace_printk is currently a wrapper function that calls
trace_vprintk. Because it uses a variable for the fmt it misses out
on the optimization of using the binary printk.

This patch makes event_trace_printk into a macro wrapper to use the
fmt as the same as the trace_printks.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace.h        |   17 +++++++++++++++++
 kernel/trace/trace_events.c |   10 ----------
 2 files changed, 17 insertions(+), 10 deletions(-)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index cede1ab..35cfa7b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -773,4 +773,21 @@ void event_trace_printk(unsigned long ip, const char *fmt, ...);
 extern struct ftrace_event_call __start_ftrace_events[];
 extern struct ftrace_event_call __stop_ftrace_events[];
 
+extern const char *__start___trace_bprintk_fmt[];
+extern const char *__stop___trace_bprintk_fmt[];
+
+#define event_trace_printk(ip, fmt, args...)				\
+do {									\
+	__trace_printk_check_format(fmt, ##args);			\
+	tracing_record_cmdline(current);				\
+	if (__builtin_constant_p(fmt)) {				\
+		static const char *trace_printk_fmt			\
+		  __attribute__((section("__trace_printk_fmt"))) =	\
+			__builtin_constant_p(fmt) ? fmt : NULL;		\
+									\
+		__trace_bprintk(ip, trace_printk_fmt, ##args);		\
+	} else								\
+		__trace_printk(ip, fmt, ##args);			\
+} while (0)
+
 #endif /* _LINUX_KERNEL_TRACE_H */
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index ca624df..238ea95 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -24,16 +24,6 @@ static DEFINE_MUTEX(event_mutex);
 	     (unsigned long)event < (unsigned long)__stop_ftrace_events; \
 	     event++)
 
-void event_trace_printk(unsigned long ip, const char *fmt, ...)
-{
-	va_list ap;
-
-	va_start(ap, fmt);
-	tracing_record_cmdline(current);
-	trace_vprintk(ip, task_curr_ret_stack(current), fmt, ap);
-	va_end(ap);
-}
-
 static void ftrace_clear_events(void)
 {
 	struct ftrace_event_call *call = (void *)__start_ftrace_events;
-- 
1.6.1.3

-- 

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[Andrew Morton]

On Thu, 12 Mar 2009 22:37:12 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:

> +		static const char *trace_printk_fmt			\
> +		  __attribute__((section("__trace_printk_fmt"))) =	\
> +			__builtin_constant_p(fmt) ? fmt : NULL;		\

hm.  Does this put trace_printk_fmt into the __trace_printk_fmt
section, or does it put *trace_printk_fmt in there?

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[Steven Rostedt]

On Thu, 12 Mar 2009, Andrew Morton wrote:

> On Thu, 12 Mar 2009 22:37:12 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > +		static const char *trace_printk_fmt			\
> > +		  __attribute__((section("__trace_printk_fmt"))) =	\
> > +			__builtin_constant_p(fmt) ? fmt : NULL;		\
> 
> hm.  Does this put trace_printk_fmt into the __trace_printk_fmt
> section, or does it put *trace_printk_fmt in there?

We save the pointer into that section:

 0xc0432100:   "my format is to print this number %d\n"

  [...]

section <__trace_printk_fmt>:
  [...]
 0xc0483210:   0xc0432100  (trace_printk_fmt)


It would be difficult to make the string be located in the section when 
the caller simply does:

   trace_printk("my format is to print this number %d\n", mynum);

Although I guess we could try by using [] = fmt, but the pointer just 
seemed easier.

Note, for modules, we have a hash of all strings/pointers. When a module 
is loaded, we copy the strings into the hash (if it is not already there) 
and keep it loaded, even if the module is removed. This is because the 
pointer to this string would still be around inside the trace buffer.

-- Steve

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[KOSAKI Motohiro]

> +#define event_trace_printk(ip, fmt, args...)				\
> +do {									\
> +	__trace_printk_check_format(fmt, ##args);			\
> +	tracing_record_cmdline(current);				\
> +	if (__builtin_constant_p(fmt)) {				\
> +		static const char *trace_printk_fmt			\
> +		  __attribute__((section("__trace_printk_fmt"))) =	\
> +			__builtin_constant_p(fmt) ? fmt : NULL;		\

Why __builtin_constant_p(fmt) evaluate twice?


> +									\
> +		__trace_bprintk(ip, trace_printk_fmt, ##args);		\
> +	} else								\
> +		__trace_printk(ip, fmt, ##args);			\
> +} while (0)

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[Steven Rostedt]

On Fri, 13 Mar 2009, KOSAKI Motohiro wrote:

> > +#define event_trace_printk(ip, fmt, args...)				\
> > +do {									\
> > +	__trace_printk_check_format(fmt, ##args);			\
> > +	tracing_record_cmdline(current);				\
> > +	if (__builtin_constant_p(fmt)) {				\
> > +		static const char *trace_printk_fmt			\
> > +		  __attribute__((section("__trace_printk_fmt"))) =	\
> > +			__builtin_constant_p(fmt) ? fmt : NULL;		\
> 
> Why __builtin_constant_p(fmt) evaluate twice?

It's explained in another patch. But this was a real PITA. We first tried 
this with just the "if (__builtin_return_p(fmt))" but the way gcc works, 
it handles the global data assignments before optimizing out condition 
logic. Thus we ended up getting errors about can not initialize static 
variable with a non constant.

But the ? : operation of the assignment is optimized before the assignment
is made. Thus, if fmt is not constant, then we avoid this warning. Then
during the conditional optimization, gcc will remove that part of the code 
altogether.

Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out 
one of them and see what happens with:

myfunc(const char *fmt) {

  event_trace_printk(fmt);

}

Of course the way this is made, we may not call it that way, but I wanted 
to be safe.

-- Steve

> 
> 
> > +									\
> > +		__trace_bprintk(ip, trace_printk_fmt, ##args);		\
> > +	} else								\
> > +		__trace_printk(ip, fmt, ##args);			\
> > +} while (0)
> 
> 
> 

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[KOSAKI Motohiro]

> > > +#define event_trace_printk(ip, fmt, args...)				\
> > > +do {									\
> > > +	__trace_printk_check_format(fmt, ##args);			\
> > > +	tracing_record_cmdline(current);				\
> > > +	if (__builtin_constant_p(fmt)) {				\
> > > +		static const char *trace_printk_fmt			\
> > > +		  __attribute__((section("__trace_printk_fmt"))) =	\
> > > +			__builtin_constant_p(fmt) ? fmt : NULL;		\
> > 
> > Why __builtin_constant_p(fmt) evaluate twice?
> 
> It's explained in another patch. But this was a real PITA. We first tried 
> this with just the "if (__builtin_return_p(fmt))" but the way gcc works, 
> it handles the global data assignments before optimizing out condition 
> logic. Thus we ended up getting errors about can not initialize static 
> variable with a non constant.
> 
> But the ? : operation of the assignment is optimized before the assignment
> is made. Thus, if fmt is not constant, then we avoid this warning. Then
> during the conditional optimization, gcc will remove that part of the code 
> altogether.
> 
> Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out 
> one of them and see what happens with:
> 
> myfunc(const char *fmt) {
> 
>   event_trace_printk(fmt);
> 
> }
> 
> Of course the way this is made, we may not call it that way, but I wanted 
> to be safe.

Thanks for kindful explain.
So, I guess many developer feel it's strange. 
adding comment is better?

Re: [PATCH 08/16] tracing: have event_trace_printk use static tracer

[Steven Rostedt]

On Fri, 13 Mar 2009, KOSAKI Motohiro wrote:

> > > > +#define event_trace_printk(ip, fmt, args...)				\
> > > > +do {									\
> > > > +	__trace_printk_check_format(fmt, ##args);			\
> > > > +	tracing_record_cmdline(current);				\
> > > > +	if (__builtin_constant_p(fmt)) {				\
> > > > +		static const char *trace_printk_fmt			\
> > > > +		  __attribute__((section("__trace_printk_fmt"))) =	\
> > > > +			__builtin_constant_p(fmt) ? fmt : NULL;		\
> > > 
> > > Why __builtin_constant_p(fmt) evaluate twice?
> > 
> > It's explained in another patch. But this was a real PITA. We first tried 
> > this with just the "if (__builtin_return_p(fmt))" but the way gcc works, 
> > it handles the global data assignments before optimizing out condition 
> > logic. Thus we ended up getting errors about can not initialize static 
> > variable with a non constant.
> > 
> > But the ? : operation of the assignment is optimized before the assignment
> > is made. Thus, if fmt is not constant, then we avoid this warning. Then
> > during the conditional optimization, gcc will remove that part of the code 
> > altogether.
> > 
> > Thus the double __builtin_constant_p(fmt) is needed twice. Try taking out 
> > one of them and see what happens with:
> > 
> > myfunc(const char *fmt) {
> > 
> >   event_trace_printk(fmt);
> > 
> > }
> > 
> > Of course the way this is made, we may not call it that way, but I wanted 
> > to be safe.
> 
> Thanks for kindful explain.
> So, I guess many developer feel it's strange. 
> adding comment is better?

Yeah, I cut and pasted this out from the trace_printk in kernel.h where I 
had the comment there. But I think you are right, I probably should copy 
that comment here too.

-- Steve

[tip:tracing/ftrace] tracing: add comment for use of double __builtin_consant_p

[Steven Rostedt]

Commit-ID:  bdc067582b8b71c7771bab076bbc51569c594fb4
Gitweb:     http://git.kernel.org/tip/bdc067582b8b71c7771bab076bbc51569c594fb4
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Fri, 13 Mar 2009 00:12:52 -0400
Commit:     Steven Rostedt <srostedt@redhat.com>
CommitDate: Fri, 13 Mar 2009 00:15:46 -0400

tracing: add comment for use of double __builtin_consant_p

Impact: documentation

The use of the double __builtin_contant_p checks in the event_trace_printk
can be confusing to developers and reviewers. This patch adds a comment
to explain why it is there.

Requested-by: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
LKML-Reference: <20090313122235.43EB.A69D9226@jp.fujitsu.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>


---
 kernel/trace/trace.h |    5 +++++
 1 files changed, 5 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 35cfa7b..67595b8 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -776,6 +776,11 @@ extern struct ftrace_event_call __stop_ftrace_events[];
 extern const char *__start___trace_bprintk_fmt[];
 extern const char *__stop___trace_bprintk_fmt[];
 
+/*
+ * The double __builtin_constant_p is because gcc will give us an error
+ * if we try to allocate the static variable to fmt if it is not a
+ * constant. Even with the outer if statement optimizing out.
+ */
 #define event_trace_printk(ip, fmt, args...)				\
 do {									\
 	__trace_printk_check_format(fmt, ##args);			\

[PATCH 09/16] tracing: export trace formats to user space

[Steven Rostedt]

[-- Attachment #1: 0009-tracing-export-trace-formats-to-user-space.patch --]
[-- Type: text/plain, Size: 3760 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The binary printk saves a pointer to the format string in the ring buffer.
On output, the format is processed. But if the user is reading the
ring buffer through a binary interface, the pointer is meaningless.

This patch creates a file called printk_formats that maps the pointers
to the formats.

 # cat /debug/tracing/printk_formats
0xffffffff80713d40 : "irq_handler_entry: irq=%d handler=%s\n"
0xffffffff80713d48 : "lock_acquire: %s%s%s\n"
0xffffffff80713d50 : "lock_release: %s\n"

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_printk.c |  119 +++++++++++++++++++++++++++++++++++++++++--
 1 files changed, 114 insertions(+), 5 deletions(-)

diff --git a/kernel/trace/trace_printk.c b/kernel/trace/trace_printk.c
index f307a11..4867852 100644
--- a/kernel/trace/trace_printk.c
+++ b/kernel/trace/trace_printk.c
@@ -4,18 +4,19 @@
  * Copyright (C) 2008 Lai Jiangshan <laijs@cn.fujitsu.com>
  *
  */
+#include <linux/seq_file.h>
+#include <linux/debugfs.h>
+#include <linux/uaccess.h>
 #include <linux/kernel.h>
 #include <linux/ftrace.h>
 #include <linux/string.h>
+#include <linux/module.h>
+#include <linux/marker.h>
+#include <linux/mutex.h>
 #include <linux/ctype.h>
 #include <linux/list.h>
-#include <linux/mutex.h>
 #include <linux/slab.h>
-#include <linux/module.h>
-#include <linux/seq_file.h>
 #include <linux/fs.h>
-#include <linux/marker.h>
-#include <linux/uaccess.h>
 
 #include "trace.h"
 
@@ -153,6 +154,114 @@ int __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap)
 }
 EXPORT_SYMBOL_GPL(__ftrace_vprintk);
 
+static void *
+t_next(struct seq_file *m, void *v, loff_t *pos)
+{
+	const char **fmt = m->private;
+	const char **next = fmt;
+
+	(*pos)++;
+
+	if ((unsigned long)fmt >= (unsigned long)__stop___trace_bprintk_fmt)
+		return NULL;
+
+	next = fmt;
+	m->private = ++next;
+
+	return fmt;
+}
+
+static void *t_start(struct seq_file *m, loff_t *pos)
+{
+	return t_next(m, NULL, pos);
+}
+
+static int t_show(struct seq_file *m, void *v)
+{
+	const char **fmt = v;
+	const char *str = *fmt;
+	int i;
+
+	seq_printf(m, "0x%lx : \"", (unsigned long)fmt);
+
+	/*
+	 * Tabs and new lines need to be converted.
+	 */
+	for (i = 0; str[i]; i++) {
+		switch (str[i]) {
+		case '\n':
+			seq_puts(m, "\\n");
+			break;
+		case '\t':
+			seq_puts(m, "\\t");
+			break;
+		case '\\':
+			seq_puts(m, "\\");
+			break;
+		case '"':
+			seq_puts(m, "\\\"");
+			break;
+		default:
+			seq_putc(m, str[i]);
+		}
+	}
+	seq_puts(m, "\"\n");
+
+	return 0;
+}
+
+static void t_stop(struct seq_file *m, void *p)
+{
+}
+
+static const struct seq_operations show_format_seq_ops = {
+	.start = t_start,
+	.next = t_next,
+	.show = t_show,
+	.stop = t_stop,
+};
+
+static int
+ftrace_formats_open(struct inode *inode, struct file *file)
+{
+	int ret;
+
+	ret = seq_open(file, &show_format_seq_ops);
+	if (!ret) {
+		struct seq_file *m = file->private_data;
+
+		m->private = __start___trace_bprintk_fmt;
+	}
+	return ret;
+}
+
+static const struct file_operations ftrace_formats_fops = {
+	.open = ftrace_formats_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = seq_release,
+};
+
+static __init int init_trace_printk_function_export(void)
+{
+	struct dentry *d_tracer;
+	struct dentry *entry;
+
+	d_tracer = tracing_init_dentry();
+	if (!d_tracer)
+		return 0;
+
+	entry = debugfs_create_file("printk_formats", 0444, d_tracer,
+				    NULL, &ftrace_formats_fops);
+	if (!entry)
+		pr_warning("Could not create debugfs "
+			   "'printk_formats' entry\n");
+
+	return 0;
+}
+
+fs_initcall(init_trace_printk_function_export);
+
 static __init int init_trace_printk(void)
 {
 	return register_module_notifier(&module_trace_bprintk_format_nb);
-- 
1.6.1.3

-- 

Re: [PATCH 09/16] tracing: export trace formats to user space

[Frederic Weisbecker]

On Thu, Mar 12, 2009 at 10:37:13PM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> The binary printk saves a pointer to the format string in the ring buffer.
> On output, the format is processed. But if the user is reading the
> ring buffer through a binary interface, the pointer is meaningless.
> 
> This patch creates a file called printk_formats that maps the pointers
> to the formats.
> 
>  # cat /debug/tracing/printk_formats
> 0xffffffff80713d40 : "irq_handler_entry: irq=%d handler=%s\n"
> 0xffffffff80713d48 : "lock_acquire: %s%s%s\n"
> 0xffffffff80713d50 : "lock_release: %s\n"
> 
> Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> ---
>  kernel/trace/trace_printk.c |  119 +++++++++++++++++++++++++++++++++++++++++--
>  1 files changed, 114 insertions(+), 5 deletions(-)
> 
> diff --git a/kernel/trace/trace_printk.c b/kernel/trace/trace_printk.c
> index f307a11..4867852 100644
> --- a/kernel/trace/trace_printk.c
> +++ b/kernel/trace/trace_printk.c
> @@ -4,18 +4,19 @@
>   * Copyright (C) 2008 Lai Jiangshan <laijs@cn.fujitsu.com>
>   *
>   */
> +#include <linux/seq_file.h>
> +#include <linux/debugfs.h>
> +#include <linux/uaccess.h>
>  #include <linux/kernel.h>
>  #include <linux/ftrace.h>
>  #include <linux/string.h>
> +#include <linux/module.h>
> +#include <linux/marker.h>
> +#include <linux/mutex.h>
>  #include <linux/ctype.h>
>  #include <linux/list.h>
> -#include <linux/mutex.h>
>  #include <linux/slab.h>
> -#include <linux/module.h>
> -#include <linux/seq_file.h>
>  #include <linux/fs.h>
> -#include <linux/marker.h>
> -#include <linux/uaccess.h>
>  
>  #include "trace.h"
>  
> @@ -153,6 +154,114 @@ int __ftrace_vprintk(unsigned long ip, const char *fmt, va_list ap)
>  }
>  EXPORT_SYMBOL_GPL(__ftrace_vprintk);
>  
> +static void *
> +t_next(struct seq_file *m, void *v, loff_t *pos)
> +{
> +	const char **fmt = m->private;
> +	const char **next = fmt;
> +
> +	(*pos)++;
> +
> +	if ((unsigned long)fmt >= (unsigned long)__stop___trace_bprintk_fmt)
> +		return NULL;
> +
> +	next = fmt;
> +	m->private = ++next;
> +
> +	return fmt;
> +}
> +
> +static void *t_start(struct seq_file *m, loff_t *pos)
> +{
> +	return t_next(m, NULL, pos);
> +}
> +
> +static int t_show(struct seq_file *m, void *v)
> +{
> +	const char **fmt = v;
> +	const char *str = *fmt;
> +	int i;
> +
> +	seq_printf(m, "0x%lx : \"", (unsigned long)fmt);
> +
> +	/*
> +	 * Tabs and new lines need to be converted.
> +	 */
> +	for (i = 0; str[i]; i++) {
> +		switch (str[i]) {
> +		case '\n':
> +			seq_puts(m, "\\n");
> +			break;
> +		case '\t':
> +			seq_puts(m, "\\t");
> +			break;
> +		case '\\':
> +			seq_puts(m, "\\");
> +			break;
> +		case '"':
> +			seq_puts(m, "\\\"");
> +			break;
> +		default:
> +			seq_putc(m, str[i]);
> +		}
> +	}
> +	seq_puts(m, "\"\n");
> +
> +	return 0;
> +}
> +
> +static void t_stop(struct seq_file *m, void *p)
> +{
> +}
> +
> +static const struct seq_operations show_format_seq_ops = {
> +	.start = t_start,
> +	.next = t_next,
> +	.show = t_show,
> +	.stop = t_stop,
> +};
> +
> +static int
> +ftrace_formats_open(struct inode *inode, struct file *file)
> +{
> +	int ret;
> +
> +	ret = seq_open(file, &show_format_seq_ops);
> +	if (!ret) {
> +		struct seq_file *m = file->private_data;
> +
> +		m->private = __start___trace_bprintk_fmt;
> +	}
> +	return ret;
> +}
> +
> +static const struct file_operations ftrace_formats_fops = {
> +	.open = ftrace_formats_open,
> +	.read = seq_read,
> +	.llseek = seq_lseek,
> +	.release = seq_release,
> +};
> +
> +static __init int init_trace_printk_function_export(void)
> +{
> +	struct dentry *d_tracer;
> +	struct dentry *entry;
> +
> +	d_tracer = tracing_init_dentry();
> +	if (!d_tracer)
> +		return 0;
> +
> +	entry = debugfs_create_file("printk_formats", 0444, d_tracer,
> +				    NULL, &ftrace_formats_fops);
> +	if (!entry)
> +		pr_warning("Could not create debugfs "
> +			   "'printk_formats' entry\n");
> +
> +	return 0;
> +}
> +
> +fs_initcall(init_trace_printk_function_export);
> +
>  static __init int init_trace_printk(void)
>  {
>  	return register_module_notifier(&module_trace_bprintk_format_nb);
> -- 
> 1.6.1.3
> 
> -- 

If I remember well, a very similar patch as in the first bprintk serie sent by Lai
in december. I should have include it. Anyway it's too late :)

[PATCH 10/16] tracing: fix stack tracer header

[Steven Rostedt]

[-- Attachment #1: 0010-tracing-fix-stack-tracer-header.patch --]
[-- Type: text/plain, Size: 1400 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The stack tracer use to look like this:

 # cat /debug/tracing/stack_trace
         Depth  Size      Location    (57 entries)
         -----  ----      --------
  0)     5088      16   mempool_alloc_slab+0x16/0x18
  1)     5072     144   mempool_alloc+0x4d/0xfe
  2)     4928      16   scsi_sg_alloc+0x48/0x4a [scsi_mod]

Now it looks like this:

 # cat /debug/tracing/stack_trace

        Depth    Size      Location    (57 entries)
        -----    ----      --------
  0)     5088      16   mempool_alloc_slab+0x16/0x18
  1)     5072     144   mempool_alloc+0x4d/0xfe
  2)     4928      16   scsi_sg_alloc+0x48/0x4a [scsi_mod]

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_stack.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_stack.c b/kernel/trace/trace_stack.c
index d0871bc..4564fd9 100644
--- a/kernel/trace/trace_stack.c
+++ b/kernel/trace/trace_stack.c
@@ -251,9 +251,9 @@ static int t_show(struct seq_file *m, void *v)
 	int size;
 
 	if (v == SEQ_START_TOKEN) {
-		seq_printf(m, "        Depth   Size      Location"
+		seq_printf(m, "        Depth    Size      Location"
 			   "    (%d entries)\n"
-			   "        -----   ----      --------\n",
+			   "        -----    ----      --------\n",
 			   max_stack_trace.nr_entries);
 		return 0;
 	}
-- 
1.6.1.3

-- 

[PATCH 11/16] tracing: explain why stack tracer is empty

[Steven Rostedt]

[-- Attachment #1: 0011-tracing-explain-why-stack-tracer-is-empty.patch --]
[-- Type: text/plain, Size: 1756 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

If the stack tracing is disabled (by default) the stack_trace file
will only contain the header:

 # cat /debug/tracing/stack_trace
        Depth    Size      Location    (0 entries)
        -----    ----      --------

This can be frustrating to a developer that does not realize that the
stack tracer is disabled. This patch adds the following text:

  # cat /debug/tracing/stack_trace
        Depth    Size      Location    (0 entries)
        -----    ----      --------
 #
 #  Stack tracer disabled
 #
 # To enable the stack tracer, either add 'stacktrace' to the
 # kernel command line
 # or 'echo 1 > /proc/sys/kernel/stack_tracer_enabled'
 #

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_stack.c |   15 +++++++++++++++
 1 files changed, 15 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_stack.c b/kernel/trace/trace_stack.c
index 4564fd9..91ccbf3 100644
--- a/kernel/trace/trace_stack.c
+++ b/kernel/trace/trace_stack.c
@@ -245,6 +245,17 @@ static int trace_lookup_stack(struct seq_file *m, long i)
 #endif
 }
 
+static void print_disabled(struct seq_file *m)
+{
+	seq_puts(m, "#\n"
+		 "#  Stack tracer disabled\n"
+		 "#\n"
+		 "# To enable the stack tracer, either add 'stacktrace' to the\n"
+		 "# kernel command line\n"
+		 "# or 'echo 1 > /proc/sys/kernel/stack_tracer_enabled'\n"
+		 "#\n");
+}
+
 static int t_show(struct seq_file *m, void *v)
 {
 	long i;
@@ -255,6 +266,10 @@ static int t_show(struct seq_file *m, void *v)
 			   "    (%d entries)\n"
 			   "        -----    ----      --------\n",
 			   max_stack_trace.nr_entries);
+
+		if (!stack_tracer_enabled && !max_stack_size)
+			print_disabled(m);
+
 		return 0;
 	}
 
-- 
1.6.1.3

-- 

[PATCH 12/16] tracing: tracepoints for softirq entry/exit - add softirq-to-name array

[Steven Rostedt]

[-- Attachment #1: 0012-tracing-tracepoints-for-softirq-entry-exit-add-so.patch --]
[-- Type: text/plain, Size: 2089 bytes --]

From: Jason Baron <jbaron@redhat.com>

Create a 'softirq_to_name' array, which is indexed by softirq #, so
that we can easily convert between the softirq index # and its name, in
order to get more meaningful output messages.

LKML-Reference: <20090312183336.GB3352@redhat.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/interrupt.h |    5 +++++
 kernel/softirq.c          |    9 ++++++++-
 2 files changed, 13 insertions(+), 1 deletions(-)

diff --git a/include/linux/interrupt.h b/include/linux/interrupt.h
index 472f117..9b7e9d7 100644
--- a/include/linux/interrupt.h
+++ b/include/linux/interrupt.h
@@ -258,6 +258,11 @@ enum
 	NR_SOFTIRQS
 };
 
+/* map softirq index to softirq name. update 'softirq_to_name' in
+ * kernel/softirq.c when adding a new softirq.
+ */
+extern char *softirq_to_name[NR_SOFTIRQS];
+
 /* softirq mask and active fields moved to irq_cpustat_t in
  * asm/hardirq.h to get better cache usage.  KAO
  */
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 7571bcb..9f90fdc 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -53,6 +53,12 @@ static struct softirq_action softirq_vec[NR_SOFTIRQS] __cacheline_aligned_in_smp
 
 static DEFINE_PER_CPU(struct task_struct *, ksoftirqd);
 
+char *softirq_to_name[NR_SOFTIRQS] = {
+	"HI_SOFTIRQ", "TIMER_SOFTIRQ", "NET_TX_SOFTIRQ", "NET_RX_SOFTIRQ",
+	"BLOCK_SOFTIRQ", "TASKLET_SOFTIRQ", "SCHED_SOFTIRQ", "HRTIMER_SOFTIRQ",
+	"RCU_SOFTIRQ"
+};
+
 /*
  * we cannot loop indefinitely here to avoid userspace starvation,
  * but we also don't want to introduce a worst case 1/HZ latency
@@ -209,9 +215,10 @@ restart:
 			h->action(h);
 
 			if (unlikely(prev_count != preempt_count())) {
-				printk(KERN_ERR "huh, entered softirq %td %p"
+				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
 				       " exited with %08x?\n", h - softirq_vec,
+				       softirq_to_name[h - softirq_vec],
 				       h->action, prev_count, preempt_count());
 				preempt_count() = prev_count;
 			}
-- 
1.6.1.3

-- 

Re: [PATCH 12/16] tracing: tracepoints for softirq entry/exit - add softirq-to-name array

[Andrew Morton]

On Thu, 12 Mar 2009 22:37:16 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:

> +char *softirq_to_name[NR_SOFTIRQS] = {
> +	"HI_SOFTIRQ", "TIMER_SOFTIRQ", "NET_TX_SOFTIRQ", "NET_RX_SOFTIRQ",
> +	"BLOCK_SOFTIRQ", "TASKLET_SOFTIRQ", "SCHED_SOFTIRQ", "HRTIMER_SOFTIRQ",
> +	"RCU_SOFTIRQ"
> +};

	"HI", "TIMER", "NET_TX", "NET_RX",
	"BLOCK", "TASKLET", "SCHED", "HRTIMER",
	"RCU"

would suffice.

Re: [PATCH 12/16] tracing: tracepoints for softirq entry/exit - add softirq-to-name array

[Steven Rostedt]

On Thu, 12 Mar 2009, Andrew Morton wrote:

> On Thu, 12 Mar 2009 22:37:16 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > +char *softirq_to_name[NR_SOFTIRQS] = {
> > +	"HI_SOFTIRQ", "TIMER_SOFTIRQ", "NET_TX_SOFTIRQ", "NET_RX_SOFTIRQ",
> > +	"BLOCK_SOFTIRQ", "TASKLET_SOFTIRQ", "SCHED_SOFTIRQ", "HRTIMER_SOFTIRQ",
> > +	"RCU_SOFTIRQ"
> > +};
> 
> 	"HI", "TIMER", "NET_TX", "NET_RX",
> 	"BLOCK", "TASKLET", "SCHED", "HRTIMER",
> 	"RCU"
> 
> would suffice.


OK, will update.

Thanks,

-- Steve

[PATCH 13/16] tracing: tracepoints for softirq entry/exit - tracepoints

[Steven Rostedt]

[-- Attachment #1: 0013-tracing-tracepoints-for-softirq-entry-exit-tracep.patch --]
[-- Type: text/plain, Size: 2165 bytes --]

From: Jason Baron <jbaron@redhat.com>

Introduce softirq entry/exit tracepoints. These are useful for
augmenting existing tracers, and to figure out softirq frequencies and
timings.

[
  s/irq_softirq_/softirq_/ for trace point names and
  Fixed printf format in TRACE_FORMAT macro
   - Steven Rostedt
]

LKML-Reference: <20090312183603.GC3352@redhat.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/trace/irq_event_types.h |   12 ++++++++++++
 kernel/softirq.c                |    7 ++++++-
 2 files changed, 18 insertions(+), 1 deletions(-)

diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 214bb92..85964eb 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
 		  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
+TRACE_FORMAT(softirq_entry,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", (int)(h - vec), softirq_to_name[h-vec])
+	);
+
+TRACE_FORMAT(softirq_exit,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", (int)(h - vec), softirq_to_name[h-vec])
+	);
+
 #undef TRACE_SYSTEM
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 9f90fdc..a5e8123 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -24,6 +24,7 @@
 #include <linux/ftrace.h>
 #include <linux/smp.h>
 #include <linux/tick.h>
+#include <trace/irq.h>
 
 #include <asm/irq.h>
 /*
@@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
  */
 #define MAX_SOFTIRQ_RESTART 10
 
+DEFINE_TRACE(softirq_entry);
+DEFINE_TRACE(softirq_exit);
+
 asmlinkage void __do_softirq(void)
 {
 	struct softirq_action *h;
@@ -212,8 +216,9 @@ restart:
 		if (pending & 1) {
 			int prev_count = preempt_count();
 
+			trace_softirq_entry(h, softirq_vec);
 			h->action(h);
-
+			trace_softirq_exit(h, softirq_vec);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"
-- 
1.6.1.3

-- 

[PATCH 14/16] tracing: Dont use tracing_record_cmdline() in workqueue tracer fix

[Steven Rostedt]

[-- Attachment #1: 0014-tracing-Don-t-use-tracing_record_cmdline-in-workq.patch --]
[-- Type: text/plain, Size: 1540 bytes --]

From: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>

commit c3ffc7a40b7e94b094efe1c8ab4e24370a782b65
"Don't use tracing_record_cmdline() in workqueue tracer"
has a race window.

find_task_by_vpid() requires task_list_lock().

LKML-Reference: <20090313090042.43CD.A69D9226@jp.fujitsu.com>
Signed-off-by: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_workqueue.c |   20 ++++++++++++++------
 1 files changed, 14 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index fb5ccac..9ab035b 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -193,12 +193,20 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
 	struct cpu_workqueue_stats *cws = p;
 	unsigned long flags;
 	int cpu = cws->cpu;
-	struct task_struct *tsk = find_task_by_vpid(cws->pid);
-
-	seq_printf(s, "%3d %6d     %6u       %s\n", cws->cpu,
-		   atomic_read(&cws->inserted),
-		   cws->executed,
-		   tsk ? tsk->comm : "<...>");
+	struct pid *pid;
+	struct task_struct *tsk;
+
+	pid = find_get_pid(cws->pid);
+	if (pid) {
+		tsk = get_pid_task(pid, PIDTYPE_PID);
+		if (tsk) {
+			seq_printf(s, "%3d %6d     %6u       %s\n", cws->cpu,
+				   atomic_read(&cws->inserted), cws->executed,
+				   tsk->comm);
+			put_task_struct(tsk);
+		}
+		put_pid(pid);
+	}
 
 	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
 	if (&cws->list == workqueue_cpu_stat(cpu)->list.next)
-- 
1.6.1.3

-- 

[PATCH 15/16] tracing: show event name in trace for TRACE_EVENT created events

[Steven Rostedt]

[-- Attachment #1: 0015-tracing-show-event-name-in-trace-for-TRACE_EVENT-cr.patch --]
[-- Type: text/plain, Size: 1019 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Unlike TRACE_FORMAT() macros, the TRACE_EVENT() macros do not show
the event name in the trace file. Knowing the event type in the trace
output is very useful.

Instead of:

   task swapper:0 [140] ==> ntpd:3308 [120]

We now have:

   sched_switch: task swapper:0 [140] ==> ntpd:3308 [120]

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace_events_stage_2.h |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_events_stage_2.h b/kernel/trace/trace_events_stage_2.h
index ca347af..5117c43 100644
--- a/kernel/trace/trace_events_stage_2.h
+++ b/kernel/trace/trace_events_stage_2.h
@@ -57,7 +57,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 									\
 	field = (typeof(field))entry;					\
 									\
-	ret = trace_seq_printf(s, print);				\
+	ret = trace_seq_printf(s, #call ": " print);			\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\
-- 
1.6.1.3

-- 

[PATCH 16/16] ring-buffer: document reader page design

[Steven Rostedt]

[-- Attachment #1: 0016-ring-buffer-document-reader-page-design.patch --]
[-- Type: text/plain, Size: 3235 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

In a private email conversation I explained how the ring buffer
page worked by using silly ASCII art. Ingo suggested that I add
that to the comments of the code.

Here it is.

Requested-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/ring_buffer.c |   68 ++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 68 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 2c36be9..58128ad 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -22,6 +22,74 @@
 #include "trace.h"
 
 /*
+ * The ring buffer is made up of a list of pages. A separate list of pages is
+ * allocated for each CPU. A writer may only write to a buffer that is
+ * associated with the CPU it is currently executing on.  A reader may read
+ * from any per cpu buffer.
+ *
+ * The reader is special. For each per cpu buffer, the reader has its own
+ * reader page. When a reader has read the entire reader page, this reader
+ * page is swapped with another page in the ring buffer.
+ *
+ * Now, as long as the writer is off the reader page, the reader can do what
+ * ever it wants with that page. The writer will never write to that page
+ * again (as long as it is out of the ring buffer).
+ *
+ * Here's some silly ASCII art.
+ *
+ *   +------+
+ *   |reader|          RING BUFFER
+ *   |page  |
+ *   +------+        +---+   +---+   +---+
+ *                   |   |-->|   |-->|   |
+ *                   +---+   +---+   +---+
+ *                     ^               |
+ *                     |               |
+ *                     +---------------+
+ *
+ *
+ *   +------+
+ *   |reader|          RING BUFFER
+ *   |page  |------------------v
+ *   +------+        +---+   +---+   +---+
+ *                   |   |-->|   |-->|   |
+ *                   +---+   +---+   +---+
+ *                     ^               |
+ *                     |               |
+ *                     +---------------+
+ *
+ *
+ *   +------+
+ *   |reader|          RING BUFFER
+ *   |page  |------------------v
+ *   +------+        +---+   +---+   +---+
+ *      ^            |   |-->|   |-->|   |
+ *      |            +---+   +---+   +---+
+ *      |                              |
+ *      |                              |
+ *      +------------------------------+
+ *
+ *
+ *   +------+
+ *   |buffer|          RING BUFFER
+ *   |page  |------------------v
+ *   +------+        +---+   +---+   +---+
+ *      ^            |   |   |   |-->|   |
+ *      |   New      +---+   +---+   +---+
+ *      |  Reader------^               |
+ *      |   page                       |
+ *      +------------------------------+
+ *
+ *
+ * After we make this swap, the reader can hand this page off to the splice
+ * code and be done with it. It can even allocate a new page if it needs to
+ * and swap that into the ring buffer.
+ *
+ * We will be using cmpxchg soon to make all this lockless.
+ *
+ */
+
+/*
  * A fast way to enable or disable all ring buffers is to
  * call tracing_on or tracing_off. Turning off the ring buffers
  * prevents all ring buffers from being recorded to.
-- 
1.6.1.3

-- 

Re: [PATCH 00/16] [GIT PULL] updates for tip/tracing/ftrace

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> Ingo,
> 
> Please pull the latest tip/tracing/ftrace tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace
> 
> 
> Frederic Weisbecker (1):
>       tracing/core: bring back raw trace_printk for dynamic formats strings
> 
> Jason Baron (2):
>       tracing: tracepoints for softirq entry/exit - add softirq-to-name array
>       tracing: tracepoints for softirq entry/exit - tracepoints
> 
> KOSAKI Motohiro (1):
>       tracing: Don't use tracing_record_cmdline() in workqueue tracer fix
> 
> Steven Rostedt (12):
>       tracing: fix comments about trace buffer resizing
>       tracing: protect ring_buffer_expanded with trace_types_lock
>       ring-buffer: use CONFIG_HOTPLUG_CPU not CONFIG_HOTPLUG
>       ring-buffer: remove unneeded get_online_cpus
>       tracing: show that buffer size is not expanded
>       tracing: make bprint event use the proper event id
>       tracing: have event_trace_printk use static tracer
>       tracing: export trace formats to user space
>       tracing: fix stack tracer header
>       tracing: explain why stack tracer is empty
>       tracing: show event name in trace for TRACE_EVENT created events
>       ring-buffer: document reader page design
> 
> ----
>  include/linux/interrupt.h            |    5 +
>  include/linux/kernel.h               |   40 ++++++---
>  include/trace/irq_event_types.h      |   12 +++
>  kernel/softirq.c                     |   16 +++-
>  kernel/trace/ring_buffer.c           |  168 +++++++++++++++++----------------
>  kernel/trace/trace.c                 |  121 ++++++++++++++++++++++--
>  kernel/trace/trace.h                 |   30 ++++++-
>  kernel/trace/trace_event_types.h     |   11 ++-
>  kernel/trace/trace_events.c          |   10 --
>  kernel/trace/trace_events_stage_2.h  |    2 +-
>  kernel/trace/trace_functions_graph.c |    6 +-
>  kernel/trace/trace_mmiotrace.c       |    7 +-
>  kernel/trace/trace_output.c          |   57 ++++++++++-
>  kernel/trace/trace_printk.c          |  150 ++++++++++++++++++++++++++++--
>  kernel/trace/trace_stack.c           |   19 ++++-
>  kernel/trace/trace_workqueue.c       |   20 +++-
>  16 files changed, 523 insertions(+), 151 deletions(-)

Pulled, thanks Steve!

	Ingo