linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH v2 0/2] ftrace: printk formatted recording
@ 2008-08-01 16:26 Steven Rostedt
  2008-08-01 16:26 ` [PATCH v2 1/2] ftrace: new continue entry - separate out from trace_entry Steven Rostedt
                   ` (2 more replies)
  0 siblings, 3 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 16:26 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Peter Zijlstra, Thomas Gleixner, Andrew Morton

I previously sent out a patch to add printk formatted recording to the ftrace
buffers.  Andrew Morton suggested to get rid of my hacked trace_cont structure
and do it properly with one structure at the top and two other structures
to handle the difference between the fields and the continuation entry.

That is to have a top entry:

struct trace_entry {
	char type;
	union {
		struct trace_field field;
		struct trace_cont  cont;
	};
};

instead of having a separate trace_cont that was outside the trace_entry
and would be typecasted when used. This would be a source of bugs with
later modifications of the ftrace code if a developer did not relize
the connection between trace_entry and trace_cont. Using this proper
method keeps the two tighly coupled for new developers to see.

Unfortunatly, doing it the proper way caused a large code change since
now all the users of trace_entry (and there are many) must now dereference
the field item.

The first patch just does the struct update and changes all the users
to do the dereferencing properly.

The second patch in this series adds the user of the trace_cont, which
is the ftrace_printk.

Note: I can no longer use the unspecified array size buf[] because gcc
complains about:

struct trace_cont {
	buf[];
};

I now use buf[sizeof(struct trace_field)]  which I think is a better solution
anyways.

-- Steve


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v2 1/2] ftrace: new continue entry - separate out from trace_entry
  2008-08-01 16:26 [PATCH v2 0/2] ftrace: printk formatted recording Steven Rostedt
@ 2008-08-01 16:26 ` Steven Rostedt
  2008-08-01 16:26 ` [PATCH v2 2/2] ftrace: printk formatting infrastructure Steven Rostedt
  2008-08-15 15:00 ` [PATCH v2 0/2] ftrace: printk formatted recording Ingo Molnar
  2 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 16:26 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Peter Zijlstra, Thomas Gleixner, Andrew Morton,
	Steven Rostedt

[-- Attachment #1: ftrace-separate-out-entry-struct.patch --]
[-- Type: text/plain, Size: 21748 bytes --]

Some tracers will need to work with more than one entry. In order to do this
the trace_entry structure was split into two fields. One for the start of
all entries, and one to continue an existing entry.

The trace_entry structure now has a "field" entry that consists of the previous
content of the trace_entry, and a "cont" entry that is just a string buffer
the size of the "field" entry.

Thanks to Andrew Morton for suggesting this idea.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 kernel/trace/trace.c           |  267 +++++++++++++++++++++--------------------
 kernel/trace/trace.h           |   17 ++
 kernel/trace/trace_mmiotrace.c |   12 -
 3 files changed, 160 insertions(+), 136 deletions(-)

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 10:18:00.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-08-01 12:07:36.000000000 -0400
@@ -826,10 +826,11 @@ tracing_generic_entry_update(struct trac
 
 	pc = preempt_count();
 
-	entry->preempt_count	= pc & 0xff;
-	entry->pid		= (tsk) ? tsk->pid : 0;
-	entry->t		= ftrace_now(raw_smp_processor_id());
-	entry->flags = (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
+	entry->field.preempt_count	= pc & 0xff;
+	entry->field.pid		= (tsk) ? tsk->pid : 0;
+	entry->field.t			= ftrace_now(raw_smp_processor_id());
+	entry->field.flags =
+		(irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
 		((pc & HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) |
 		((pc & SOFTIRQ_MASK) ? TRACE_FLAG_SOFTIRQ : 0) |
 		(need_resched() ? TRACE_FLAG_NEED_RESCHED : 0);
@@ -844,11 +845,11 @@ trace_function(struct trace_array *tr, s
 
 	raw_local_irq_save(irq_flags);
 	__raw_spin_lock(&data->lock);
-	entry			= tracing_get_trace_entry(tr, data);
+	entry				= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, flags);
-	entry->type		= TRACE_FN;
-	entry->fn.ip		= ip;
-	entry->fn.parent_ip	= parent_ip;
+	entry->type			= TRACE_FN;
+	entry->field.fn.ip		= ip;
+	entry->field.fn.parent_ip	= parent_ip;
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
 }
@@ -871,10 +872,10 @@ void __trace_mmiotrace_rw(struct trace_a
 	raw_local_irq_save(irq_flags);
 	__raw_spin_lock(&data->lock);
 
-	entry			= tracing_get_trace_entry(tr, data);
+	entry				= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, 0);
-	entry->type		= TRACE_MMIO_RW;
-	entry->mmiorw		= *rw;
+	entry->type			= TRACE_MMIO_RW;
+	entry->field.mmiorw		= *rw;
 
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
@@ -891,10 +892,10 @@ void __trace_mmiotrace_map(struct trace_
 	raw_local_irq_save(irq_flags);
 	__raw_spin_lock(&data->lock);
 
-	entry			= tracing_get_trace_entry(tr, data);
+	entry				= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, 0);
-	entry->type		= TRACE_MMIO_MAP;
-	entry->mmiomap		= *map;
+	entry->type			= TRACE_MMIO_MAP;
+	entry->field.mmiomap		= *map;
 
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
@@ -918,12 +919,12 @@ void __trace_stack(struct trace_array *t
 	tracing_generic_entry_update(entry, flags);
 	entry->type		= TRACE_STACK;
 
-	memset(&entry->stack, 0, sizeof(entry->stack));
+	memset(&entry->field.stack, 0, sizeof(entry->field.stack));
 
 	trace.nr_entries	= 0;
 	trace.max_entries	= FTRACE_STACK_ENTRIES;
 	trace.skip		= skip;
-	trace.entries		= entry->stack.caller;
+	trace.entries		= entry->field.stack.caller;
 
 	save_stack_trace(&trace);
 }
@@ -939,12 +940,12 @@ __trace_special(void *__tr, void *__data
 
 	raw_local_irq_save(irq_flags);
 	__raw_spin_lock(&data->lock);
-	entry			= tracing_get_trace_entry(tr, data);
+	entry				= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, 0);
-	entry->type		= TRACE_SPECIAL;
-	entry->special.arg1	= arg1;
-	entry->special.arg2	= arg2;
-	entry->special.arg3	= arg3;
+	entry->type			= TRACE_SPECIAL;
+	entry->field.special.arg1	= arg1;
+	entry->field.special.arg2	= arg2;
+	entry->field.special.arg3	= arg3;
 	__trace_stack(tr, data, irq_flags, 4);
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
@@ -964,15 +965,15 @@ tracing_sched_switch_trace(struct trace_
 
 	raw_local_irq_save(irq_flags);
 	__raw_spin_lock(&data->lock);
-	entry			= tracing_get_trace_entry(tr, data);
+	entry				= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, flags);
-	entry->type		= TRACE_CTX;
-	entry->ctx.prev_pid	= prev->pid;
-	entry->ctx.prev_prio	= prev->prio;
-	entry->ctx.prev_state	= prev->state;
-	entry->ctx.next_pid	= next->pid;
-	entry->ctx.next_prio	= next->prio;
-	entry->ctx.next_state	= next->state;
+	entry->type			= TRACE_CTX;
+	entry->field.ctx.prev_pid	= prev->pid;
+	entry->field.ctx.prev_prio	= prev->prio;
+	entry->field.ctx.prev_state	= prev->state;
+	entry->field.ctx.next_pid	= next->pid;
+	entry->field.ctx.next_prio	= next->prio;
+	entry->field.ctx.next_state	= next->state;
 	__trace_stack(tr, data, flags, 5);
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
@@ -993,12 +994,12 @@ tracing_sched_wakeup_trace(struct trace_
 	entry			= tracing_get_trace_entry(tr, data);
 	tracing_generic_entry_update(entry, flags);
 	entry->type		= TRACE_WAKE;
-	entry->ctx.prev_pid	= curr->pid;
-	entry->ctx.prev_prio	= curr->prio;
-	entry->ctx.prev_state	= curr->state;
-	entry->ctx.next_pid	= wakee->pid;
-	entry->ctx.next_prio	= wakee->prio;
-	entry->ctx.next_state	= wakee->state;
+	entry->field.ctx.prev_pid	= curr->pid;
+	entry->field.ctx.prev_prio	= curr->prio;
+	entry->field.ctx.prev_state	= curr->state;
+	entry->field.ctx.next_pid	= wakee->pid;
+	entry->field.ctx.next_prio	= wakee->prio;
+	entry->field.ctx.next_state	= wakee->state;
 	__trace_stack(tr, data, flags, 6);
 	__raw_spin_unlock(&data->lock);
 	raw_local_irq_restore(irq_flags);
@@ -1127,7 +1128,7 @@ find_next_entry(struct trace_iterator *i
 		/*
 		 * Pick the entry with the smallest timestamp:
 		 */
-		if (ent && (!next || ent->t < next->t)) {
+		if (ent && (!next || ent->field.t < next->field.t)) {
 			next = ent;
 			next_cpu = cpu;
 		}
@@ -1431,19 +1432,20 @@ print_trace_header(struct seq_file *m, s
 static void
 lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
 {
+	struct trace_field *field = &entry->field;
 	int hardirq, softirq;
 	char *comm;
 
-	comm = trace_find_cmdline(entry->pid);
+	comm = trace_find_cmdline(field->pid);
 
-	trace_seq_printf(s, "%8.8s-%-5d ", comm, entry->pid);
+	trace_seq_printf(s, "%8.8s-%-5d ", comm, field->pid);
 	trace_seq_printf(s, "%d", cpu);
 	trace_seq_printf(s, "%c%c",
-			(entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' : '.',
-			((entry->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
+			(field->flags & TRACE_FLAG_IRQS_OFF) ? 'd' : '.',
+			((field->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
 
-	hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
-	softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
+	hardirq = field->flags & TRACE_FLAG_HARDIRQ;
+	softirq = field->flags & TRACE_FLAG_SOFTIRQ;
 	if (hardirq && softirq) {
 		trace_seq_putc(s, 'H');
 	} else {
@@ -1457,8 +1459,8 @@ lat_print_generic(struct trace_seq *s, s
 		}
 	}
 
-	if (entry->preempt_count)
-		trace_seq_printf(s, "%x", entry->preempt_count);
+	if (field->preempt_count)
+		trace_seq_printf(s, "%x", field->preempt_count);
 	else
 		trace_seq_puts(s, ".");
 }
@@ -1488,6 +1490,7 @@ print_lat_fmt(struct trace_iterator *ite
 	struct trace_entry *next_entry = find_next_entry(iter, NULL);
 	unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);
 	struct trace_entry *entry = iter->ent;
+	struct trace_field *field = &entry->field;
 	unsigned long abs_usecs;
 	unsigned long rel_usecs;
 	char *comm;
@@ -1497,17 +1500,17 @@ print_lat_fmt(struct trace_iterator *ite
 
 	if (!next_entry)
 		next_entry = entry;
-	rel_usecs = ns2usecs(next_entry->t - entry->t);
-	abs_usecs = ns2usecs(entry->t - iter->tr->time_start);
+	rel_usecs = ns2usecs(next_entry->field.t - entry->field.t);
+	abs_usecs = ns2usecs(entry->field.t - iter->tr->time_start);
 
 	if (verbose) {
-		comm = trace_find_cmdline(entry->pid);
+		comm = trace_find_cmdline(field->pid);
 		trace_seq_printf(s, "%16s %5d %d %d %08x %08x [%08lx]"
 				 " %ld.%03ldms (+%ld.%03ldms): ",
 				 comm,
-				 entry->pid, cpu, entry->flags,
-				 entry->preempt_count, trace_idx,
-				 ns2usecs(entry->t),
+				 field->pid, cpu, field->flags,
+				 field->preempt_count, trace_idx,
+				 ns2usecs(field->t),
 				 abs_usecs/1000,
 				 abs_usecs % 1000, rel_usecs/1000,
 				 rel_usecs % 1000);
@@ -1517,41 +1520,42 @@ print_lat_fmt(struct trace_iterator *ite
 	}
 	switch (entry->type) {
 	case TRACE_FN:
-		seq_print_ip_sym(s, entry->fn.ip, sym_flags);
+		seq_print_ip_sym(s, field->fn.ip, sym_flags);
 		trace_seq_puts(s, " (");
-		if (kretprobed(entry->fn.parent_ip))
+		if (kretprobed(field->fn.parent_ip))
 			trace_seq_puts(s, KRETPROBE_MSG);
 		else
-			seq_print_ip_sym(s, entry->fn.parent_ip, sym_flags);
+			seq_print_ip_sym(s, field->fn.parent_ip, sym_flags);
 		trace_seq_puts(s, ")\n");
 		break;
 	case TRACE_CTX:
 	case TRACE_WAKE:
-		T = entry->ctx.next_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.next_state] : 'X';
+		T = field->ctx.next_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.next_state] : 'X';
 
-		state = entry->ctx.prev_state ? __ffs(entry->ctx.prev_state) + 1 : 0;
+		state = field->ctx.prev_state ?
+			__ffs(field->ctx.prev_state) + 1 : 0;
 		S = state < sizeof(state_to_char) - 1 ? state_to_char[state] : 'X';
-		comm = trace_find_cmdline(entry->ctx.next_pid);
+		comm = trace_find_cmdline(field->ctx.next_pid);
 		trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c %s\n",
-				 entry->ctx.prev_pid,
-				 entry->ctx.prev_prio,
+				 field->ctx.prev_pid,
+				 field->ctx.prev_prio,
 				 S, entry->type == TRACE_CTX ? "==>" : "  +",
-				 entry->ctx.next_pid,
-				 entry->ctx.next_prio,
+				 field->ctx.next_pid,
+				 field->ctx.next_prio,
 				 T, comm);
 		break;
 	case TRACE_SPECIAL:
 		trace_seq_printf(s, "# %ld %ld %ld\n",
-				 entry->special.arg1,
-				 entry->special.arg2,
-				 entry->special.arg3);
+				 field->special.arg1,
+				 field->special.arg2,
+				 field->special.arg3);
 		break;
 	case TRACE_STACK:
 		for (i = 0; i < FTRACE_STACK_ENTRIES; i++) {
 			if (i)
 				trace_seq_puts(s, " <= ");
-			seq_print_ip_sym(s, entry->stack.caller[i], sym_flags);
+			seq_print_ip_sym(s, field->stack.caller[i], sym_flags);
 		}
 		trace_seq_puts(s, "\n");
 		break;
@@ -1566,6 +1570,7 @@ static int print_trace_fmt(struct trace_
 	struct trace_seq *s = &iter->seq;
 	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
 	struct trace_entry *entry;
+	struct trace_field *field;
 	unsigned long usec_rem;
 	unsigned long long t;
 	unsigned long secs;
@@ -1575,14 +1580,15 @@ static int print_trace_fmt(struct trace_
 	int i;
 
 	entry = iter->ent;
+	field = &entry->field;
 
-	comm = trace_find_cmdline(iter->ent->pid);
+	comm = trace_find_cmdline(iter->ent->field.pid);
 
-	t = ns2usecs(entry->t);
+	t = ns2usecs(field->t);
 	usec_rem = do_div(t, 1000000ULL);
 	secs = (unsigned long)t;
 
-	ret = trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid);
+	ret = trace_seq_printf(s, "%16s-%-5d ", comm, field->pid);
 	if (!ret)
 		return 0;
 	ret = trace_seq_printf(s, "[%02d] ", iter->cpu);
@@ -1594,18 +1600,19 @@ static int print_trace_fmt(struct trace_
 
 	switch (entry->type) {
 	case TRACE_FN:
-		ret = seq_print_ip_sym(s, entry->fn.ip, sym_flags);
+		ret = seq_print_ip_sym(s, field->fn.ip, sym_flags);
 		if (!ret)
 			return 0;
 		if ((sym_flags & TRACE_ITER_PRINT_PARENT) &&
-						entry->fn.parent_ip) {
+						field->fn.parent_ip) {
 			ret = trace_seq_printf(s, " <-");
 			if (!ret)
 				return 0;
-			if (kretprobed(entry->fn.parent_ip))
+			if (kretprobed(field->fn.parent_ip))
 				ret = trace_seq_puts(s, KRETPROBE_MSG);
 			else
-				ret = seq_print_ip_sym(s, entry->fn.parent_ip,
+				ret = seq_print_ip_sym(s,
+						       field->fn.parent_ip,
 						       sym_flags);
 			if (!ret)
 				return 0;
@@ -1616,26 +1623,26 @@ static int print_trace_fmt(struct trace_
 		break;
 	case TRACE_CTX:
 	case TRACE_WAKE:
-		S = entry->ctx.prev_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.prev_state] : 'X';
-		T = entry->ctx.next_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.next_state] : 'X';
+		S = field->ctx.prev_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.prev_state] : 'X';
+		T = field->ctx.next_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.next_state] : 'X';
 		ret = trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c\n",
-				       entry->ctx.prev_pid,
-				       entry->ctx.prev_prio,
+				       field->ctx.prev_pid,
+				       field->ctx.prev_prio,
 				       S,
 				       entry->type == TRACE_CTX ? "==>" : "  +",
-				       entry->ctx.next_pid,
-				       entry->ctx.next_prio,
+				       field->ctx.next_pid,
+				       field->ctx.next_prio,
 				       T);
 		if (!ret)
 			return 0;
 		break;
 	case TRACE_SPECIAL:
 		ret = trace_seq_printf(s, "# %ld %ld %ld\n",
-				 entry->special.arg1,
-				 entry->special.arg2,
-				 entry->special.arg3);
+				 field->special.arg1,
+				 field->special.arg2,
+				 field->special.arg3);
 		if (!ret)
 			return 0;
 		break;
@@ -1646,7 +1653,7 @@ static int print_trace_fmt(struct trace_
 				if (!ret)
 					return 0;
 			}
-			ret = seq_print_ip_sym(s, entry->stack.caller[i],
+			ret = seq_print_ip_sym(s, field->stack.caller[i],
 					       sym_flags);
 			if (!ret)
 				return 0;
@@ -1663,37 +1670,40 @@ static int print_raw_fmt(struct trace_it
 {
 	struct trace_seq *s = &iter->seq;
 	struct trace_entry *entry;
+	struct trace_field *field;
 	int ret;
 	int S, T;
 
 	entry = iter->ent;
+	field = &entry->field;
 
 	ret = trace_seq_printf(s, "%d %d %llu ",
-		entry->pid, iter->cpu, entry->t);
+		field->pid, iter->cpu, field->t);
 	if (!ret)
 		return 0;
 
 	switch (entry->type) {
 	case TRACE_FN:
 		ret = trace_seq_printf(s, "%x %x\n",
-					entry->fn.ip, entry->fn.parent_ip);
+					field->fn.ip,
+					field->fn.parent_ip);
 		if (!ret)
 			return 0;
 		break;
 	case TRACE_CTX:
 	case TRACE_WAKE:
-		S = entry->ctx.prev_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.prev_state] : 'X';
-		T = entry->ctx.next_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.next_state] : 'X';
+		S = field->ctx.prev_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.prev_state] : 'X';
+		T = field->ctx.next_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.next_state] : 'X';
 		if (entry->type == TRACE_WAKE)
 			S = '+';
 		ret = trace_seq_printf(s, "%d %d %c %d %d %c\n",
-				       entry->ctx.prev_pid,
-				       entry->ctx.prev_prio,
+				       field->ctx.prev_pid,
+				       field->ctx.prev_prio,
 				       S,
-				       entry->ctx.next_pid,
-				       entry->ctx.next_prio,
+				       field->ctx.next_pid,
+				       field->ctx.next_prio,
 				       T);
 		if (!ret)
 			return 0;
@@ -1701,9 +1711,9 @@ static int print_raw_fmt(struct trace_it
 	case TRACE_SPECIAL:
 	case TRACE_STACK:
 		ret = trace_seq_printf(s, "# %ld %ld %ld\n",
-				 entry->special.arg1,
-				 entry->special.arg2,
-				 entry->special.arg3);
+				 field->special.arg1,
+				 field->special.arg2,
+				 field->special.arg3);
 		if (!ret)
 			return 0;
 		break;
@@ -1728,40 +1738,41 @@ static int print_hex_fmt(struct trace_it
 	struct trace_seq *s = &iter->seq;
 	unsigned char newline = '\n';
 	struct trace_entry *entry;
+	struct trace_field *field;
 	int S, T;
 
 	entry = iter->ent;
+	field = &entry->field;
 
-	SEQ_PUT_HEX_FIELD_RET(s, entry->pid);
+	SEQ_PUT_HEX_FIELD_RET(s, field->pid);
 	SEQ_PUT_HEX_FIELD_RET(s, iter->cpu);
-	SEQ_PUT_HEX_FIELD_RET(s, entry->t);
+	SEQ_PUT_HEX_FIELD_RET(s, field->t);
 
 	switch (entry->type) {
 	case TRACE_FN:
-		SEQ_PUT_HEX_FIELD_RET(s, entry->fn.ip);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->fn.parent_ip);
+		SEQ_PUT_HEX_FIELD_RET(s, field->fn.ip);
+		SEQ_PUT_HEX_FIELD_RET(s, field->fn.parent_ip);
 		break;
 	case TRACE_CTX:
 	case TRACE_WAKE:
-		S = entry->ctx.prev_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.prev_state] : 'X';
-		T = entry->ctx.next_state < sizeof(state_to_char) ?
-			state_to_char[entry->ctx.next_state] : 'X';
+		S = field->ctx.prev_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.prev_state] : 'X';
+		T = field->ctx.next_state < sizeof(state_to_char) ?
+			state_to_char[field->ctx.next_state] : 'X';
 		if (entry->type == TRACE_WAKE)
 			S = '+';
-		SEQ_PUT_HEX_FIELD_RET(s, entry->ctx.prev_pid);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->ctx.prev_prio);
+		SEQ_PUT_HEX_FIELD_RET(s, field->ctx.prev_pid);
+		SEQ_PUT_HEX_FIELD_RET(s, field->ctx.prev_prio);
 		SEQ_PUT_HEX_FIELD_RET(s, S);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->ctx.next_pid);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->ctx.next_prio);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->fn.parent_ip);
+		SEQ_PUT_HEX_FIELD_RET(s, field->ctx.next_pid);
+		SEQ_PUT_HEX_FIELD_RET(s, field->ctx.next_prio);
 		SEQ_PUT_HEX_FIELD_RET(s, T);
 		break;
 	case TRACE_SPECIAL:
 	case TRACE_STACK:
-		SEQ_PUT_HEX_FIELD_RET(s, entry->special.arg1);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->special.arg2);
-		SEQ_PUT_HEX_FIELD_RET(s, entry->special.arg3);
+		SEQ_PUT_HEX_FIELD_RET(s, field->special.arg1);
+		SEQ_PUT_HEX_FIELD_RET(s, field->special.arg2);
+		SEQ_PUT_HEX_FIELD_RET(s, field->special.arg3);
 		break;
 	}
 	SEQ_PUT_FIELD_RET(s, newline);
@@ -1773,31 +1784,33 @@ static int print_bin_fmt(struct trace_it
 {
 	struct trace_seq *s = &iter->seq;
 	struct trace_entry *entry;
+	struct trace_field *field;
 
 	entry = iter->ent;
+	field = &entry->field;
 
-	SEQ_PUT_FIELD_RET(s, entry->pid);
-	SEQ_PUT_FIELD_RET(s, entry->cpu);
-	SEQ_PUT_FIELD_RET(s, entry->t);
+	SEQ_PUT_FIELD_RET(s, field->pid);
+	SEQ_PUT_FIELD_RET(s, field->cpu);
+	SEQ_PUT_FIELD_RET(s, field->t);
 
 	switch (entry->type) {
 	case TRACE_FN:
-		SEQ_PUT_FIELD_RET(s, entry->fn.ip);
-		SEQ_PUT_FIELD_RET(s, entry->fn.parent_ip);
+		SEQ_PUT_FIELD_RET(s, field->fn.ip);
+		SEQ_PUT_FIELD_RET(s, field->fn.parent_ip);
 		break;
 	case TRACE_CTX:
-		SEQ_PUT_FIELD_RET(s, entry->ctx.prev_pid);
-		SEQ_PUT_FIELD_RET(s, entry->ctx.prev_prio);
-		SEQ_PUT_FIELD_RET(s, entry->ctx.prev_state);
-		SEQ_PUT_FIELD_RET(s, entry->ctx.next_pid);
-		SEQ_PUT_FIELD_RET(s, entry->ctx.next_prio);
-		SEQ_PUT_FIELD_RET(s, entry->ctx.next_state);
+		SEQ_PUT_FIELD_RET(s, field->ctx.prev_pid);
+		SEQ_PUT_FIELD_RET(s, field->ctx.prev_prio);
+		SEQ_PUT_FIELD_RET(s, field->ctx.prev_state);
+		SEQ_PUT_FIELD_RET(s, field->ctx.next_pid);
+		SEQ_PUT_FIELD_RET(s, field->ctx.next_prio);
+		SEQ_PUT_FIELD_RET(s, field->ctx.next_state);
 		break;
 	case TRACE_SPECIAL:
 	case TRACE_STACK:
-		SEQ_PUT_FIELD_RET(s, entry->special.arg1);
-		SEQ_PUT_FIELD_RET(s, entry->special.arg2);
-		SEQ_PUT_FIELD_RET(s, entry->special.arg3);
+		SEQ_PUT_FIELD_RET(s, field->special.arg1);
+		SEQ_PUT_FIELD_RET(s, field->special.arg2);
+		SEQ_PUT_FIELD_RET(s, field->special.arg3);
 		break;
 	}
 	return 1;
Index: linux-tip.git/kernel/trace/trace.h
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.h	2008-08-01 10:18:00.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.h	2008-08-01 11:55:08.000000000 -0400
@@ -61,13 +61,12 @@ struct stack_entry {
 };
 
 /*
- * The trace entry - the most basic unit of tracing. This is what
+ * The trace field - the most basic unit of tracing. This is what
  * is printed in the end as a single line in the trace output, such as:
  *
  *     bash-15816 [01]   235.197585: idle_cpu <- irq_enter
  */
-struct trace_entry {
-	char			type;
+struct trace_field {
 	char			cpu;
 	char			flags;
 	char			preempt_count;
@@ -83,6 +82,18 @@ struct trace_entry {
 	};
 };
 
+struct trace_field_cont {
+	char				buf[sizeof(struct trace_field)];
+};
+
+struct trace_entry {
+	char 				type;
+	union {
+		struct trace_field	field;
+		struct trace_field_cont	cont;
+	};
+};
+
 #define TRACE_ENTRY_SIZE	sizeof(struct trace_entry)
 
 /*
Index: linux-tip.git/kernel/trace/trace_mmiotrace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_mmiotrace.c	2008-08-01 10:46:33.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_mmiotrace.c	2008-08-01 11:03:12.000000000 -0400
@@ -174,14 +174,14 @@ print_out:
 static int mmio_print_rw(struct trace_iterator *iter)
 {
 	struct trace_entry *entry = iter->ent;
-	struct mmiotrace_rw *rw	= &entry->mmiorw;
+	struct mmiotrace_rw *rw	= &entry->field.mmiorw;
 	struct trace_seq *s	= &iter->seq;
-	unsigned long long t	= ns2usecs(entry->t);
+	unsigned long long t	= ns2usecs(entry->field.t);
 	unsigned long usec_rem	= do_div(t, 1000000ULL);
 	unsigned secs		= (unsigned long)t;
 	int ret = 1;
 
-	switch (entry->mmiorw.opcode) {
+	switch (entry->field.mmiorw.opcode) {
 	case MMIO_READ:
 		ret = trace_seq_printf(s,
 			"R %d %lu.%06lu %d 0x%llx 0x%lx 0x%lx %d\n",
@@ -216,14 +216,14 @@ static int mmio_print_rw(struct trace_it
 static int mmio_print_map(struct trace_iterator *iter)
 {
 	struct trace_entry *entry = iter->ent;
-	struct mmiotrace_map *m	= &entry->mmiomap;
+	struct mmiotrace_map *m	= &entry->field.mmiomap;
 	struct trace_seq *s	= &iter->seq;
-	unsigned long long t	= ns2usecs(entry->t);
+	unsigned long long t	= ns2usecs(entry->field.t);
 	unsigned long usec_rem	= do_div(t, 1000000ULL);
 	unsigned secs		= (unsigned long)t;
 	int ret = 1;
 
-	switch (entry->mmiorw.opcode) {
+	switch (entry->field.mmiorw.opcode) {
 	case MMIO_PROBE:
 		ret = trace_seq_printf(s,
 			"MAP %lu.%06lu %d 0x%llx 0x%lx 0x%lx 0x%lx %d\n",

-- 

^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v2 2/2] ftrace: printk formatting infrastructure
  2008-08-01 16:26 [PATCH v2 0/2] ftrace: printk formatted recording Steven Rostedt
  2008-08-01 16:26 ` [PATCH v2 1/2] ftrace: new continue entry - separate out from trace_entry Steven Rostedt
@ 2008-08-01 16:26 ` Steven Rostedt
  2008-08-01 16:43   ` Randy Dunlap
  2008-08-15 15:00 ` [PATCH v2 0/2] ftrace: printk formatted recording Ingo Molnar
  2 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 16:26 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Peter Zijlstra, Thomas Gleixner, Andrew Morton,
	Steven Rostedt

[-- Attachment #1: ftrace-printk.patch --]
[-- Type: text/plain, Size: 16041 bytes --]

This patch adds a feature that can help kernel developers debug their
code using ftrace.

  int ftrace_printk(const char *fmt, ...);

This records into the ftrace buffer using printf formatting. The entry
size in the buffers are still a fixed length. A new type has been added
that allows for more entries to be used for a single recording.

The start of the print is still the same as the other entries.

It returns the number of characters written to the ftrace buffer.


For example:

Having a module with the following code:

static int __init ftrace_print_test(void)
{
        ftrace_printk("jiffies are %ld\n", jiffies);
        return 0;
}

Gives me:

  insmod-5441  3...1 7569us : ftrace_print_test: jiffies are 4296626666

for the latency_trace file and:

          insmod-5441  [03]  1959.370498: ftrace_print_test jiffies are 4296626666

for the trace file.

Note: Only the infrastructure should go into the kernel. It is to help 
facilitate debugging for other kernel developers. Calls to ftrace_printk 
is not intended to be left in the kernel, and should be frowned upon just 
like scattering printks around in the code.

But having this easily at your fingertips helps the debugging go faster 
and bugs be solved quicker.

Maybe later on, we can hook this with markers and have their printf format 
be sucked into ftrace output.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/ftrace.h        |   10 +
 kernel/trace/trace.c          |  273 +++++++++++++++++++++++++++++++++++++-----
 kernel/trace/trace.h          |   11 +
 kernel/trace/trace_selftest.c |   11 +
 4 files changed, 272 insertions(+), 33 deletions(-)

Index: linux-tip.git/include/linux/ftrace.h
===================================================================
--- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 11:55:08.000000000 -0400
+++ linux-tip.git/include/linux/ftrace.h	2008-08-01 12:09:11.000000000 -0400
@@ -137,10 +137,20 @@ static inline void tracer_disable(void)
 extern void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
 extern void ftrace_dump(void);
+# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
+extern int
+__ftrace_printk(unsigned long ip, const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
 #else
 static inline void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3) { }
 static inline void ftrace_dump(void) { }
+static inline int
+ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 0)))
+{
+	return 0;
+}
 #endif
 
+
 #endif /* _LINUX_FTRACE_H */
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 12:07:36.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-08-01 12:11:12.000000000 -0400
@@ -206,12 +206,14 @@ unsigned long nsecs_to_usecs(unsigned lo
  *  NEED_RESCED - reschedule is requested
  *  HARDIRQ	- inside an interrupt handler
  *  SOFTIRQ	- inside a softirq handler
+ *  CONT	- multiple entries hold the trace item
  */
 enum trace_flag_type {
 	TRACE_FLAG_IRQS_OFF		= 0x01,
 	TRACE_FLAG_NEED_RESCHED		= 0x02,
 	TRACE_FLAG_HARDIRQ		= 0x04,
 	TRACE_FLAG_SOFTIRQ		= 0x08,
+	TRACE_FLAG_CONT			= 0x10,
 };
 
 /*
@@ -1083,6 +1085,7 @@ enum trace_file_type {
 	TRACE_FILE_LAT_FMT	= 1,
 };
 
+/* Return the current entry.  */
 static struct trace_entry *
 trace_entry_idx(struct trace_array *tr, struct trace_array_cpu *data,
 		struct trace_iterator *iter, int cpu)
@@ -1113,8 +1116,58 @@ trace_entry_idx(struct trace_array *tr, 
 	return &array[iter->next_page_idx[cpu]];
 }
 
+/* Increment the index counter of an iterator by one */
+static void trace_iterator_increment(struct trace_iterator *iter, int cpu)
+{
+	iter->idx++;
+	iter->next_idx[cpu]++;
+	iter->next_page_idx[cpu]++;
+
+	if (iter->next_page_idx[cpu] >= ENTRIES_PER_PAGE) {
+		struct trace_array_cpu *data = iter->tr->data[cpu];
+
+		iter->next_page_idx[cpu] = 0;
+		iter->next_page[cpu] =
+			trace_next_list(data, iter->next_page[cpu]);
+	}
+}
+
 static struct trace_entry *
-find_next_entry(struct trace_iterator *iter, int *ent_cpu)
+trace_entry_next(struct trace_array *tr, struct trace_array_cpu *data,
+		 struct trace_iterator *iter, int cpu)
+{
+	struct list_head *next_page;
+	struct trace_entry *ent;
+	int idx, next_idx, next_page_idx;
+
+	ent = trace_entry_idx(tr, tr->data[cpu], iter, cpu);
+
+	if (likely(!ent || ent->type != TRACE_CONT))
+		return ent;
+
+	/* save the iterator details */
+	idx		= iter->idx;
+	next_idx	= iter->next_idx[cpu];
+	next_page_idx	= iter->next_page_idx[cpu];
+	next_page	= iter->next_page[cpu];
+
+	/* find a real entry */
+	do {
+		trace_iterator_increment(iter, cpu);
+		ent = trace_entry_idx(tr, tr->data[cpu], iter, cpu);
+	} while (ent && ent->type != TRACE_CONT);
+
+	/* reset the iterator */
+	iter->idx			= idx;
+	iter->next_idx[cpu]		= next_idx;
+	iter->next_page_idx[cpu]	= next_page_idx;
+	iter->next_page[cpu]		= next_page;
+
+	return ent;
+}
+
+static struct trace_entry *
+__find_next_entry(struct trace_iterator *iter, int *ent_cpu, int inc)
 {
 	struct trace_array *tr = iter->tr;
 	struct trace_entry *ent, *next = NULL;
@@ -1124,7 +1177,23 @@ find_next_entry(struct trace_iterator *i
 	for_each_tracing_cpu(cpu) {
 		if (!head_page(tr->data[cpu]))
 			continue;
+
 		ent = trace_entry_idx(tr, tr->data[cpu], iter, cpu);
+
+		if (ent && ent->type == TRACE_CONT) {
+			struct trace_array_cpu *data = tr->data[cpu];
+
+			if (!inc)
+				ent = trace_entry_next(tr, data, iter, cpu);
+			else {
+				while (ent && ent->type == TRACE_CONT) {
+					trace_iterator_increment(iter, cpu);
+					ent = trace_entry_idx(tr, tr->data[cpu],
+							      iter, cpu);
+				}
+			}
+		}
+
 		/*
 		 * Pick the entry with the smallest timestamp:
 		 */
@@ -1140,25 +1209,39 @@ find_next_entry(struct trace_iterator *i
 	return next;
 }
 
-static void trace_iterator_increment(struct trace_iterator *iter)
+/* Find the next real entry, without updating the iterator itself */
+static struct trace_entry *
+find_next_entry(struct trace_iterator *iter, int *ent_cpu)
 {
-	iter->idx++;
-	iter->next_idx[iter->cpu]++;
-	iter->next_page_idx[iter->cpu]++;
+	return __find_next_entry(iter, ent_cpu, 0);
+}
 
-	if (iter->next_page_idx[iter->cpu] >= ENTRIES_PER_PAGE) {
-		struct trace_array_cpu *data = iter->tr->data[iter->cpu];
+/* Find the next real entry, and increment the iterator to the next entry */
+static void *find_next_entry_inc(struct trace_iterator *iter)
+{
+	struct trace_entry *next;
+	int next_cpu = -1;
 
-		iter->next_page_idx[iter->cpu] = 0;
-		iter->next_page[iter->cpu] =
-			trace_next_list(data, iter->next_page[iter->cpu]);
-	}
+	next = __find_next_entry(iter, &next_cpu, 1);
+
+	iter->prev_ent = iter->ent;
+	iter->prev_cpu = iter->cpu;
+
+	iter->ent = next;
+	iter->cpu = next_cpu;
+
+	if (next)
+		trace_iterator_increment(iter, iter->cpu);
+
+	return next ? iter : NULL;
 }
 
 static void trace_consume(struct trace_iterator *iter)
 {
 	struct trace_array_cpu *data = iter->tr->data[iter->cpu];
+	struct trace_entry *ent;
 
+ again:
 	data->trace_tail_idx++;
 	if (data->trace_tail_idx >= ENTRIES_PER_PAGE) {
 		data->trace_tail = trace_next_page(data, data->trace_tail);
@@ -1169,25 +1252,11 @@ static void trace_consume(struct trace_i
 	if (data->trace_head == data->trace_tail &&
 	    data->trace_head_idx == data->trace_tail_idx)
 		data->trace_idx = 0;
-}
-
-static void *find_next_entry_inc(struct trace_iterator *iter)
-{
-	struct trace_entry *next;
-	int next_cpu = -1;
-
-	next = find_next_entry(iter, &next_cpu);
-
-	iter->prev_ent = iter->ent;
-	iter->prev_cpu = iter->cpu;
-
-	iter->ent = next;
-	iter->cpu = next_cpu;
 
-	if (next)
-		trace_iterator_increment(iter);
-
-	return next ? iter : NULL;
+	ent = trace_entry_idx(iter->tr, iter->tr->data[iter->cpu],
+			      iter, iter->cpu);
+	if (ent && ent->type == TRACE_CONT)
+		goto again;
 }
 
 static void *s_next(struct seq_file *m, void *v, loff_t *pos)
@@ -1482,6 +1551,26 @@ lat_print_timestamp(struct trace_seq *s,
 
 static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
 
+static void
+trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
+{
+	struct trace_array *tr = iter->tr;
+	struct trace_array_cpu *data = tr->data[iter->cpu];
+	struct trace_entry *ent;
+
+	ent = trace_entry_idx(tr, data, iter, iter->cpu);
+	if (!ent || ent->type != TRACE_CONT) {
+		trace_seq_putc(s, '\n');
+		return;
+	}
+
+	do {
+		trace_seq_printf(s, "%s", ent->cont.buf);
+		trace_iterator_increment(iter, iter->cpu);
+		ent = trace_entry_idx(tr, data, iter, iter->cpu);
+	} while (ent && ent->type == TRACE_CONT);
+}
+
 static int
 print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
 {
@@ -1500,6 +1589,10 @@ print_lat_fmt(struct trace_iterator *ite
 
 	if (!next_entry)
 		next_entry = entry;
+
+	if (entry->type == TRACE_CONT)
+		return 1;
+
 	rel_usecs = ns2usecs(next_entry->field.t - entry->field.t);
 	abs_usecs = ns2usecs(entry->field.t - iter->tr->time_start);
 
@@ -1559,6 +1652,12 @@ print_lat_fmt(struct trace_iterator *ite
 		}
 		trace_seq_puts(s, "\n");
 		break;
+	case TRACE_PRINT:
+		seq_print_ip_sym(s, field->print.ip, sym_flags);
+		trace_seq_printf(s, ": %s", field->print.buf);
+		if (field->flags && TRACE_FLAG_CONT)
+			trace_seq_print_cont(s, iter);
+		break;
 	default:
 		trace_seq_printf(s, "Unknown type %d\n", entry->type);
 	}
@@ -1580,6 +1679,10 @@ static int print_trace_fmt(struct trace_
 	int i;
 
 	entry = iter->ent;
+
+	if (entry->type == TRACE_CONT)
+		return 1;
+
 	field = &entry->field;
 
 	comm = trace_find_cmdline(iter->ent->field.pid);
@@ -1662,6 +1765,12 @@ static int print_trace_fmt(struct trace_
 		if (!ret)
 			return 0;
 		break;
+	case TRACE_PRINT:
+		seq_print_ip_sym(s, field->print.ip, sym_flags);
+		trace_seq_printf(s, ": %s", field->print.buf);
+		if (field->flags && TRACE_FLAG_CONT)
+			trace_seq_print_cont(s, iter);
+		break;
 	}
 	return 1;
 }
@@ -1675,6 +1784,10 @@ static int print_raw_fmt(struct trace_it
 	int S, T;
 
 	entry = iter->ent;
+
+	if (entry->type == TRACE_CONT)
+		return 1;
+
 	field = &entry->field;
 
 	ret = trace_seq_printf(s, "%d %d %llu ",
@@ -1717,6 +1830,12 @@ static int print_raw_fmt(struct trace_it
 		if (!ret)
 			return 0;
 		break;
+	case TRACE_PRINT:
+		trace_seq_printf(s, "# %lx %s",
+				 field->print.ip, field->print.buf);
+		if (field->flags && TRACE_FLAG_CONT)
+			trace_seq_print_cont(s, iter);
+		break;
 	}
 	return 1;
 }
@@ -1742,6 +1861,10 @@ static int print_hex_fmt(struct trace_it
 	int S, T;
 
 	entry = iter->ent;
+
+	if (entry->type == TRACE_CONT)
+		return 1;
+
 	field = &entry->field;
 
 	SEQ_PUT_HEX_FIELD_RET(s, field->pid);
@@ -1787,6 +1910,10 @@ static int print_bin_fmt(struct trace_it
 	struct trace_field *field;
 
 	entry = iter->ent;
+
+	if (entry->type == TRACE_CONT)
+		return 1;
+
 	field = &entry->field;
 
 	SEQ_PUT_FIELD_RET(s, field->pid);
@@ -3111,6 +3238,94 @@ void ftrace_dump(void)
 	spin_unlock_irqrestore(&ftrace_dump_lock, flags);
 }
 
+#define TRACE_BUF_SIZE 1024
+#define TRACE_PRINT_BUF_SIZE \
+	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
+#define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
+
+/**
+ * ftrace_printk - printf formatting in the ftrace buffer
+ * @fmt - the printf format for printing.
+ *
+ * Note: __ftrace_printk is an internal function for ftrace_printk and
+ *       the @ip is passed in via the ftrace_printk macro.
+ *
+ * This function allows a kernel developer to debug fast path sections
+ * that printk is not appropriate for. By scattering in various
+ * printk like tracing in the code, a developer can quickly see
+ * where problems are occurring.
+ *
+ * This is intended as a debugging tool for the developer only.
+ * Please reframe from leaving ftrace_printks scattered around in
+ * your code.
+ */
+int __ftrace_printk(unsigned long ip, const char *fmt, ...)
+{
+	struct trace_array *tr = &global_trace;
+	static DEFINE_SPINLOCK(trace_buf_lock);
+	static char trace_buf[TRACE_BUF_SIZE];
+	struct trace_array_cpu *data;
+	struct trace_entry *entry;
+	unsigned long flags;
+	long disabled;
+	va_list ap;
+	int cpu, len = 0, write, written = 0;
+
+	if (likely(!ftrace_function_enabled))
+		return 0;
+
+	local_irq_save(flags);
+	cpu = raw_smp_processor_id();
+	data = tr->data[cpu];
+	disabled = atomic_inc_return(&data->disabled);
+
+	if (unlikely(disabled != 1 || !ftrace_function_enabled))
+		goto out;
+
+	spin_lock(&trace_buf_lock);
+	va_start(ap, fmt);
+	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, ap);
+	va_end(ap);
+
+	len = min(len, TRACE_BUF_SIZE-1);
+	trace_buf[len] = 0;
+
+	__raw_spin_lock(&data->lock);
+	entry				= tracing_get_trace_entry(tr, data);
+	tracing_generic_entry_update(entry, flags);
+	entry->type			= TRACE_PRINT;
+	entry->field.print.ip		= ip;
+
+	write = min(len, (int)(TRACE_PRINT_BUF_SIZE-1));
+
+	memcpy(&entry->field.print.buf, trace_buf, write);
+	entry->field.print.buf[write] = 0;
+	written = write;
+
+	if (written != len)
+		entry->field.flags |= TRACE_FLAG_CONT;
+
+	while (written != len) {
+		entry = tracing_get_trace_entry(tr, data);
+
+		entry->type = TRACE_CONT;
+		write = min(len - written, (int)(TRACE_CONT_BUF_SIZE-1));
+		memcpy(&entry->cont.buf, trace_buf+written, write);
+		entry->cont.buf[write] = 0;
+		written += write;
+	}
+	__raw_spin_unlock(&data->lock);
+
+	spin_unlock(&trace_buf_lock);
+
+ out:
+	atomic_dec(&data->disabled);
+	local_irq_restore(flags);
+
+	return len;
+}
+EXPORT_SYMBOL_GPL(__ftrace_printk);
+
 static int trace_alloc_page(void)
 {
 	struct trace_array_cpu *data;
Index: linux-tip.git/kernel/trace/trace.h
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.h	2008-08-01 11:55:08.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.h	2008-08-01 12:09:11.000000000 -0400
@@ -13,7 +13,9 @@ enum trace_type {
 	TRACE_FN,
 	TRACE_CTX,
 	TRACE_WAKE,
+	TRACE_CONT,
 	TRACE_STACK,
+	TRACE_PRINT,
 	TRACE_SPECIAL,
 	TRACE_MMIO_RW,
 	TRACE_MMIO_MAP,
@@ -61,6 +63,14 @@ struct stack_entry {
 };
 
 /*
+ * ftrace_printk entry:
+ */
+struct print_entry {
+	unsigned long		ip;
+	char			buf[];
+};
+
+/*
  * The trace field - the most basic unit of tracing. This is what
  * is printed in the end as a single line in the trace output, such as:
  *
@@ -77,6 +87,7 @@ struct trace_field {
 		struct ctx_switch_entry		ctx;
 		struct special_entry		special;
 		struct stack_entry		stack;
+		struct print_entry		print;
 		struct mmiotrace_rw		mmiorw;
 		struct mmiotrace_map		mmiomap;
 	};
Index: linux-tip.git/kernel/trace/trace_selftest.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_selftest.c	2008-08-01 11:55:08.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_selftest.c	2008-08-01 12:09:11.000000000 -0400
@@ -9,7 +9,9 @@ static inline int trace_valid_entry(stru
 	case TRACE_FN:
 	case TRACE_CTX:
 	case TRACE_WAKE:
+	case TRACE_CONT:
 	case TRACE_STACK:
+	case TRACE_PRINT:
 	case TRACE_SPECIAL:
 		return 1;
 	}
@@ -120,11 +122,11 @@ int trace_selftest_startup_dynamic_traci
 					   struct trace_array *tr,
 					   int (*func)(void))
 {
-	unsigned long count;
-	int ret;
 	int save_ftrace_enabled = ftrace_enabled;
 	int save_tracer_enabled = tracer_enabled;
+	unsigned long count;
 	char *func_name;
+	int ret;
 
 	/* The ftrace test PASSED */
 	printk(KERN_CONT "PASSED\n");
@@ -157,6 +159,7 @@ int trace_selftest_startup_dynamic_traci
 	/* enable tracing */
 	tr->ctrl = 1;
 	trace->init(tr);
+
 	/* Sleep for a 1/10 of a second */
 	msleep(100);
 
@@ -212,10 +215,10 @@ int trace_selftest_startup_dynamic_traci
 int
 trace_selftest_startup_function(struct tracer *trace, struct trace_array *tr)
 {
-	unsigned long count;
-	int ret;
 	int save_ftrace_enabled = ftrace_enabled;
 	int save_tracer_enabled = tracer_enabled;
+	unsigned long count;
+	int ret;
 
 	/* make sure msleep has been recorded */
 	msleep(1);

-- 

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 2/2] ftrace: printk formatting infrastructure
  2008-08-01 16:26 ` [PATCH v2 2/2] ftrace: printk formatting infrastructure Steven Rostedt
@ 2008-08-01 16:43   ` Randy Dunlap
  2008-08-01 16:53     ` Steven Rostedt
  0 siblings, 1 reply; 13+ messages in thread
From: Randy Dunlap @ 2008-08-01 16:43 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt

On Fri, 01 Aug 2008 12:26:41 -0400 Steven Rostedt wrote:

> +/**
> + * ftrace_printk - printf formatting in the ftrace buffer
> + * @fmt - the printf format for printing.

    * @fmt: the printf format for printing
    * @ip: <description>

> + *
> + * Note: __ftrace_printk is an internal function for ftrace_printk and
> + *       the @ip is passed in via the ftrace_printk macro.
> + *
> + * This function allows a kernel developer to debug fast path sections
> + * that printk is not appropriate for. By scattering in various
> + * printk like tracing in the code, a developer can quickly see
> + * where problems are occurring.
> + *
> + * This is intended as a debugging tool for the developer only.
> + * Please reframe from leaving ftrace_printks scattered around in
> + * your code.
> + */
> +int __ftrace_printk(unsigned long ip, const char *fmt, ...)
> +{


---
~Randy
Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
http://linuxplumbersconf.org/

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 2/2] ftrace: printk formatting infrastructure
  2008-08-01 16:43   ` Randy Dunlap
@ 2008-08-01 16:53     ` Steven Rostedt
  2008-08-01 17:52       ` Randy Dunlap
  0 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 16:53 UTC (permalink / raw)
  To: Randy Dunlap
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt


On Fri, 1 Aug 2008, Randy Dunlap wrote:

> On Fri, 01 Aug 2008 12:26:41 -0400 Steven Rostedt wrote:
> 
> > +/**
> > + * ftrace_printk - printf formatting in the ftrace buffer
> > + * @fmt - the printf format for printing.
> 
>     * @fmt: the printf format for printing
>     * @ip: <description>
> 
> > + *
> > + * Note: __ftrace_printk is an internal function for ftrace_printk and
> > + *       the @ip is passed in via the ftrace_printk macro.

The above note actually explains this ;-)

Should I move the description to the ftrace_printk macro?

In include/linux/ftrace.h you see:

#ifdef CONFIG_TRACING
[...]
# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
extern int
__ftrace_printk(unsigned long ip, const char *fmt, ...)
        __attribute__ ((format (printf, 2, 3)));
#else
[...]
static inline int
ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 
0)))
{
        return 0;
}
#endif

The true API is ftrace_printk(const char *fmt) and the __ftrace_printk
version should not be used.

Do you still think I should document the @ip?

I could also just remove the passing of _THIS_IP_ and use _RET_IP_ 
inside of ftrace_printk but the _THIS_IP_ seems to be more accurate 
especially when we have stack unwinding returns.

-- Steve



> > + *
> > + * This function allows a kernel developer to debug fast path sections
> > + * that printk is not appropriate for. By scattering in various
> > + * printk like tracing in the code, a developer can quickly see
> > + * where problems are occurring.
> > + *
> > + * This is intended as a debugging tool for the developer only.
> > + * Please reframe from leaving ftrace_printks scattered around in
> > + * your code.
> > + */
> > +int __ftrace_printk(unsigned long ip, const char *fmt, ...)
> > +{
> 
> 
> ---
> ~Randy
> Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
> http://linuxplumbersconf.org/
> 

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 2/2] ftrace: printk formatting infrastructure
  2008-08-01 16:53     ` Steven Rostedt
@ 2008-08-01 17:52       ` Randy Dunlap
  2008-08-01 18:17         ` [PATCH v2 3/2] ftrace: ftrace_printk doc moved Steven Rostedt
  0 siblings, 1 reply; 13+ messages in thread
From: Randy Dunlap @ 2008-08-01 17:52 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt

On Fri, 1 Aug 2008 12:53:17 -0400 (EDT) Steven Rostedt wrote:

> 
> On Fri, 1 Aug 2008, Randy Dunlap wrote:
> 
> > On Fri, 01 Aug 2008 12:26:41 -0400 Steven Rostedt wrote:
> > 
> > > +/**
> > > + * ftrace_printk - printf formatting in the ftrace buffer
> > > + * @fmt - the printf format for printing.
> > 
> >     * @fmt: the printf format for printing
> >     * @ip: <description>
> > 
> > > + *
> > > + * Note: __ftrace_printk is an internal function for ftrace_printk and
> > > + *       the @ip is passed in via the ftrace_printk macro.
> 
> The above note actually explains this ;-)

I read that.

> Should I move the description to the ftrace_printk macro?

Probably.

> In include/linux/ftrace.h you see:
> 
> #ifdef CONFIG_TRACING
> [...]
> # define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
> extern int
> __ftrace_printk(unsigned long ip, const char *fmt, ...)
>         __attribute__ ((format (printf, 2, 3)));
> #else
> [...]
> static inline int
> ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 
> 0)))
> {
>         return 0;
> }
> #endif
> 
> The true API is ftrace_printk(const char *fmt) and the __ftrace_printk
> version should not be used.
> 
> Do you still think I should document the @ip?

Just move the kernel-doc to the macro then.

> I could also just remove the passing of _THIS_IP_ and use _RET_IP_ 
> inside of ftrace_printk but the _THIS_IP_ seems to be more accurate 
> especially when we have stack unwinding returns.
> 
> -- Steve
> 
> 
> 
> > > + *
> > > + * This function allows a kernel developer to debug fast path sections
> > > + * that printk is not appropriate for. By scattering in various
> > > + * printk like tracing in the code, a developer can quickly see
> > > + * where problems are occurring.
> > > + *
> > > + * This is intended as a debugging tool for the developer only.
> > > + * Please reframe from leaving ftrace_printks scattered around in
> > > + * your code.
> > > + */
> > > +int __ftrace_printk(unsigned long ip, const char *fmt, ...)
> > > +{


---
~Randy
Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
http://linuxplumbersconf.org/

^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v2 3/2] ftrace: ftrace_printk doc moved
  2008-08-01 17:52       ` Randy Dunlap
@ 2008-08-01 18:17         ` Steven Rostedt
  2008-08-01 20:34           ` Randy Dunlap
  0 siblings, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 18:17 UTC (permalink / raw)
  To: Randy Dunlap
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt


Based on Randy Dunlap's suggestion, the ftrace_printk kernel-doc belongs
with the ftrace_printk macro that should be used. Not with the
__ftrace_printk internal function.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/ftrace.h |   19 ++++++++++++++++++-
 kernel/trace/trace.c   |   16 ----------------
 2 files changed, 18 insertions(+), 17 deletions(-)

Index: linux-tip.git/include/linux/ftrace.h
===================================================================
--- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 12:20:56.000000000 -0400
+++ linux-tip.git/include/linux/ftrace.h	2008-08-01 14:11:13.000000000 -0400
@@ -137,7 +137,24 @@ static inline void tracer_disable(void)
 extern void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
 extern void ftrace_dump(void);
-# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
+
+/**
+ * ftrace_printk - printf formatting in the ftrace buffer
+ * @fmt - the printf format for printing.
+ *
+ * Note: __ftrace_printk is an internal function for ftrace_printk and
+ *       the @ip is passed in via the ftrace_printk macro.
+ *
+ * This function allows a kernel developer to debug fast path sections
+ * that printk is not appropriate for. By scattering in various
+ * printk like tracing in the code, a developer can quickly see
+ * where problems are occurring.
+ *
+ * This is intended as a debugging tool for the developer only.
+ * Please reframe from leaving ftrace_printks scattered around in
+ * your code.
+ */
+# define ftrace_printk(fmt...) __ftrace_printk(_THIS_IP_, fmt)
 extern int
 __ftrace_printk(unsigned long ip, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 12:20:56.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-08-01 14:10:36.000000000 -0400
@@ -3243,22 +3243,6 @@ void ftrace_dump(void)
 	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
 #define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
 
-/**
- * ftrace_printk - printf formatting in the ftrace buffer
- * @fmt - the printf format for printing.
- *
- * Note: __ftrace_printk is an internal function for ftrace_printk and
- *       the @ip is passed in via the ftrace_printk macro.
- *
- * This function allows a kernel developer to debug fast path sections
- * that printk is not appropriate for. By scattering in various
- * printk like tracing in the code, a developer can quickly see
- * where problems are occurring.
- *
- * This is intended as a debugging tool for the developer only.
- * Please reframe from leaving ftrace_printks scattered around in
- * your code.
- */
 int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 {
 	struct trace_array *tr = &global_trace;



^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 3/2] ftrace: ftrace_printk doc moved
  2008-08-01 18:17         ` [PATCH v2 3/2] ftrace: ftrace_printk doc moved Steven Rostedt
@ 2008-08-01 20:34           ` Randy Dunlap
  2008-08-01 20:42             ` Steven Rostedt
  2008-08-01 20:45             ` [PATCH v3 " Steven Rostedt
  0 siblings, 2 replies; 13+ messages in thread
From: Randy Dunlap @ 2008-08-01 20:34 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt

On Fri, 1 Aug 2008 14:17:42 -0400 (EDT) Steven Rostedt wrote:

> 
> Based on Randy Dunlap's suggestion, the ftrace_printk kernel-doc belongs
> with the ftrace_printk macro that should be used. Not with the
> __ftrace_printk internal function.
> 
> Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> ---
>  include/linux/ftrace.h |   19 ++++++++++++++++++-
>  kernel/trace/trace.c   |   16 ----------------
>  2 files changed, 18 insertions(+), 17 deletions(-)
> 
> Index: linux-tip.git/include/linux/ftrace.h
> ===================================================================
> --- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 12:20:56.000000000 -0400
> +++ linux-tip.git/include/linux/ftrace.h	2008-08-01 14:11:13.000000000 -0400
> @@ -137,7 +137,24 @@ static inline void tracer_disable(void)
>  extern void
>  ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
>  extern void ftrace_dump(void);
> -# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
> +
> +/**
> + * ftrace_printk - printf formatting in the ftrace buffer
> + * @fmt - the printf format for printing.

    * @fmt: the printf format for printing

> + *
> + * Note: __ftrace_printk is an internal function for ftrace_printk and
> + *       the @ip is passed in via the ftrace_printk macro.
> + *
> + * This function allows a kernel developer to debug fast path sections
> + * that printk is not appropriate for. By scattering in various
> + * printk like tracing in the code, a developer can quickly see
> + * where problems are occurring.
> + *
> + * This is intended as a debugging tool for the developer only.
> + * Please reframe from leaving ftrace_printks scattered around in

             refrain

> + * your code.
> + */
> +# define ftrace_printk(fmt...) __ftrace_printk(_THIS_IP_, fmt)
>  extern int
>  __ftrace_printk(unsigned long ip, const char *fmt, ...)
>  	__attribute__ ((format (printf, 2, 3)));
> Index: linux-tip.git/kernel/trace/trace.c
> ===================================================================
> --- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 12:20:56.000000000 -0400
> +++ linux-tip.git/kernel/trace/trace.c	2008-08-01 14:10:36.000000000 -0400
> @@ -3243,22 +3243,6 @@ void ftrace_dump(void)
>  	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
>  #define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
>  
> -/**
> - * ftrace_printk - printf formatting in the ftrace buffer
> - * @fmt - the printf format for printing.
> - *
> - * Note: __ftrace_printk is an internal function for ftrace_printk and
> - *       the @ip is passed in via the ftrace_printk macro.
> - *
> - * This function allows a kernel developer to debug fast path sections
> - * that printk is not appropriate for. By scattering in various
> - * printk like tracing in the code, a developer can quickly see
> - * where problems are occurring.
> - *
> - * This is intended as a debugging tool for the developer only.
> - * Please reframe from leaving ftrace_printks scattered around in
> - * your code.
> - */
>  int __ftrace_printk(unsigned long ip, const char *fmt, ...)
>  {
>  	struct trace_array *tr = &global_trace;

---
~Randy
Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
http://linuxplumbersconf.org/

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 3/2] ftrace: ftrace_printk doc moved
  2008-08-01 20:34           ` Randy Dunlap
@ 2008-08-01 20:42             ` Steven Rostedt
  2008-08-01 20:45             ` [PATCH v3 " Steven Rostedt
  1 sibling, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 20:42 UTC (permalink / raw)
  To: Randy Dunlap
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt


On Fri, 1 Aug 2008, Randy Dunlap wrote:

> On Fri, 1 Aug 2008 14:17:42 -0400 (EDT) Steven Rostedt wrote:
> 
> > 
> > Based on Randy Dunlap's suggestion, the ftrace_printk kernel-doc belongs
> > with the ftrace_printk macro that should be used. Not with the
> > __ftrace_printk internal function.
> > 
> > Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> > ---
> >  include/linux/ftrace.h |   19 ++++++++++++++++++-
> >  kernel/trace/trace.c   |   16 ----------------
> >  2 files changed, 18 insertions(+), 17 deletions(-)
> > 
> > Index: linux-tip.git/include/linux/ftrace.h
> > ===================================================================
> > --- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 12:20:56.000000000 -0400
> > +++ linux-tip.git/include/linux/ftrace.h	2008-08-01 14:11:13.000000000 -0400
> > @@ -137,7 +137,24 @@ static inline void tracer_disable(void)
> >  extern void
> >  ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
> >  extern void ftrace_dump(void);
> > -# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
> > +
> > +/**
> > + * ftrace_printk - printf formatting in the ftrace buffer
> > + * @fmt - the printf format for printing.
> 
>     * @fmt: the printf format for printing

OK, thanks.

> 
> > + *
> > + * Note: __ftrace_printk is an internal function for ftrace_printk and
> > + *       the @ip is passed in via the ftrace_printk macro.
> > + *
> > + * This function allows a kernel developer to debug fast path sections
> > + * that printk is not appropriate for. By scattering in various
> > + * printk like tracing in the code, a developer can quickly see
> > + * where problems are occurring.
> > + *
> > + * This is intended as a debugging tool for the developer only.
> > + * Please reframe from leaving ftrace_printks scattered around in
> 
>              refrain

Heh,  I manually fixed that before sending out the original. I never fixed 
it in the quilt queue. Darn!

-- Steve

> 
> > + * your code.
> > + */
> > +# define ftrace_printk(fmt...) __ftrace_printk(_THIS_IP_, fmt)
> >  extern int

^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 3/2] ftrace: ftrace_printk doc moved
  2008-08-01 20:34           ` Randy Dunlap
  2008-08-01 20:42             ` Steven Rostedt
@ 2008-08-01 20:45             ` Steven Rostedt
  2008-08-01 20:49               ` Randy Dunlap
  1 sibling, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2008-08-01 20:45 UTC (permalink / raw)
  To: Randy Dunlap
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt


Based on Randy Dunlap's suggestion, the ftrace_printk kernel-doc belongs
with the ftrace_printk macro that should be used. Not with the
__ftrace_printk internal function.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/ftrace.h |   19 ++++++++++++++++++-
 kernel/trace/trace.c   |   16 ----------------
 2 files changed, 18 insertions(+), 17 deletions(-)

Index: linux-tip.git/include/linux/ftrace.h
===================================================================
--- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 12:20:56.000000000 -0400
+++ linux-tip.git/include/linux/ftrace.h	2008-08-01 16:43:56.000000000 -0400
@@ -137,7 +137,24 @@ static inline void tracer_disable(void)
 extern void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
 extern void ftrace_dump(void);
-# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
+
+/**
+ * ftrace_printk - printf formatting in the ftrace buffer
+ * @fmt: the printf format for printing
+ *
+ * Note: __ftrace_printk is an internal function for ftrace_printk and
+ *       the @ip is passed in via the ftrace_printk macro.
+ *
+ * This function allows a kernel developer to debug fast path sections
+ * that printk is not appropriate for. By scattering in various
+ * printk like tracing in the code, a developer can quickly see
+ * where problems are occurring.
+ *
+ * This is intended as a debugging tool for the developer only.
+ * Please refrain from leaving ftrace_printks scattered around in
+ * your code.
+ */
+# define ftrace_printk(fmt...) __ftrace_printk(_THIS_IP_, fmt)
 extern int
 __ftrace_printk(unsigned long ip, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 12:20:56.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-08-01 14:10:36.000000000 -0400
@@ -3243,22 +3243,6 @@ void ftrace_dump(void)
 	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
 #define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
 
-/**
- * ftrace_printk - printf formatting in the ftrace buffer
- * @fmt - the printf format for printing.
- *
- * Note: __ftrace_printk is an internal function for ftrace_printk and
- *       the @ip is passed in via the ftrace_printk macro.
- *
- * This function allows a kernel developer to debug fast path sections
- * that printk is not appropriate for. By scattering in various
- * printk like tracing in the code, a developer can quickly see
- * where problems are occurring.
- *
- * This is intended as a debugging tool for the developer only.
- * Please reframe from leaving ftrace_printks scattered around in
- * your code.
- */
 int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 {
 	struct trace_array *tr = &global_trace;


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 3/2] ftrace: ftrace_printk doc moved
  2008-08-01 20:45             ` [PATCH v3 " Steven Rostedt
@ 2008-08-01 20:49               ` Randy Dunlap
  0 siblings, 0 replies; 13+ messages in thread
From: Randy Dunlap @ 2008-08-01 20:49 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Peter Zijlstra, Thomas Gleixner,
	Andrew Morton, Steven Rostedt

On Fri, 1 Aug 2008 16:45:49 -0400 (EDT) Steven Rostedt wrote:

> 
> Based on Randy Dunlap's suggestion, the ftrace_printk kernel-doc belongs
> with the ftrace_printk macro that should be used. Not with the
> __ftrace_printk internal function.
> 
> Signed-off-by: Steven Rostedt <srostedt@redhat.com>

Acked-by: Randy Dunlap <randy.dunlap@oracle.com>

> ---
>  include/linux/ftrace.h |   19 ++++++++++++++++++-
>  kernel/trace/trace.c   |   16 ----------------
>  2 files changed, 18 insertions(+), 17 deletions(-)
> 
> Index: linux-tip.git/include/linux/ftrace.h
> ===================================================================
> --- linux-tip.git.orig/include/linux/ftrace.h	2008-08-01 12:20:56.000000000 -0400
> +++ linux-tip.git/include/linux/ftrace.h	2008-08-01 16:43:56.000000000 -0400
> @@ -137,7 +137,24 @@ static inline void tracer_disable(void)
>  extern void
>  ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
>  extern void ftrace_dump(void);
> -# define ftrace_printk(x...) __ftrace_printk(_THIS_IP_, x)
> +
> +/**
> + * ftrace_printk - printf formatting in the ftrace buffer
> + * @fmt: the printf format for printing
> + *
> + * Note: __ftrace_printk is an internal function for ftrace_printk and
> + *       the @ip is passed in via the ftrace_printk macro.
> + *
> + * This function allows a kernel developer to debug fast path sections
> + * that printk is not appropriate for. By scattering in various
> + * printk like tracing in the code, a developer can quickly see
> + * where problems are occurring.
> + *
> + * This is intended as a debugging tool for the developer only.
> + * Please refrain from leaving ftrace_printks scattered around in
> + * your code.
> + */
> +# define ftrace_printk(fmt...) __ftrace_printk(_THIS_IP_, fmt)
>  extern int
>  __ftrace_printk(unsigned long ip, const char *fmt, ...)
>  	__attribute__ ((format (printf, 2, 3)));
> Index: linux-tip.git/kernel/trace/trace.c
> ===================================================================
> --- linux-tip.git.orig/kernel/trace/trace.c	2008-08-01 12:20:56.000000000 -0400
> +++ linux-tip.git/kernel/trace/trace.c	2008-08-01 14:10:36.000000000 -0400
> @@ -3243,22 +3243,6 @@ void ftrace_dump(void)
>  	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
>  #define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
>  
> -/**
> - * ftrace_printk - printf formatting in the ftrace buffer
> - * @fmt - the printf format for printing.
> - *
> - * Note: __ftrace_printk is an internal function for ftrace_printk and
> - *       the @ip is passed in via the ftrace_printk macro.
> - *
> - * This function allows a kernel developer to debug fast path sections
> - * that printk is not appropriate for. By scattering in various
> - * printk like tracing in the code, a developer can quickly see
> - * where problems are occurring.
> - *
> - * This is intended as a debugging tool for the developer only.
> - * Please reframe from leaving ftrace_printks scattered around in
> - * your code.
> - */
>  int __ftrace_printk(unsigned long ip, const char *fmt, ...)
>  {
>  	struct trace_array *tr = &global_trace;


---
~Randy
Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
http://linuxplumbersconf.org/

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v2 0/2] ftrace: printk formatted recording
  2008-08-01 16:26 [PATCH v2 0/2] ftrace: printk formatted recording Steven Rostedt
  2008-08-01 16:26 ` [PATCH v2 1/2] ftrace: new continue entry - separate out from trace_entry Steven Rostedt
  2008-08-01 16:26 ` [PATCH v2 2/2] ftrace: printk formatting infrastructure Steven Rostedt
@ 2008-08-15 15:00 ` Ingo Molnar
  2008-08-15 15:49   ` [PATCH] ftrace: build fix Ingo Molnar
  2 siblings, 1 reply; 13+ messages in thread
From: Ingo Molnar @ 2008-08-15 15:00 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Peter Zijlstra, Thomas Gleixner, Andrew Morton


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

> I previously sent out a patch to add printk formatted recording to the 
> ftrace buffers.  Andrew Morton suggested to get rid of my hacked 
> trace_cont structure and do it properly with one structure at the top 
> and two other structures to handle the difference between the fields 
> and the continuation entry.

applied all 3 patches to tip/tracing/ftrace - thanks Steve.

	Ingo

^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH] ftrace: build fix
  2008-08-15 15:00 ` [PATCH v2 0/2] ftrace: printk formatted recording Ingo Molnar
@ 2008-08-15 15:49   ` Ingo Molnar
  0 siblings, 0 replies; 13+ messages in thread
From: Ingo Molnar @ 2008-08-15 15:49 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Peter Zijlstra, Thomas Gleixner, Andrew Morton


>From 00968bd78e3346f35dc809f7a7c811a3d88cf07c Mon Sep 17 00:00:00 2001
From: Ingo Molnar <mingo@elte.hu>
Date: Fri, 15 Aug 2008 17:48:02 +0200
Subject: [PATCH] ftrace: build fix
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

fix:

 In file included from init/main.c:65:
 include/linux/ftrace.h:166: error: expected ‘,' or ‘;' before ‘{' token
 make[1]: *** [init/main.o] Error 1
 make: *** [init/main.o] Error 2

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 include/linux/ftrace.h |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index f0d8e48..0d19aab 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -162,7 +162,10 @@ extern void ftrace_dump(void);
 static inline void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3) { }
 static inline int
-ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 0)))
+ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 0)));
+
+static inline int
+ftrace_printk(const char *fmt, ...)
 {
 	return 0;
 }

^ permalink raw reply related	[flat|nested] 13+ messages in thread

end of thread, other threads:[~2008-08-15 15:49 UTC | newest]

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2008-08-01 16:26 [PATCH v2 0/2] ftrace: printk formatted recording Steven Rostedt
2008-08-01 16:26 ` [PATCH v2 1/2] ftrace: new continue entry - separate out from trace_entry Steven Rostedt
2008-08-01 16:26 ` [PATCH v2 2/2] ftrace: printk formatting infrastructure Steven Rostedt
2008-08-01 16:43   ` Randy Dunlap
2008-08-01 16:53     ` Steven Rostedt
2008-08-01 17:52       ` Randy Dunlap
2008-08-01 18:17         ` [PATCH v2 3/2] ftrace: ftrace_printk doc moved Steven Rostedt
2008-08-01 20:34           ` Randy Dunlap
2008-08-01 20:42             ` Steven Rostedt
2008-08-01 20:45             ` [PATCH v3 " Steven Rostedt
2008-08-01 20:49               ` Randy Dunlap
2008-08-15 15:00 ` [PATCH v2 0/2] ftrace: printk formatted recording Ingo Molnar
2008-08-15 15:49   ` [PATCH] ftrace: build fix Ingo Molnar

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).