[Patch] Tracing/ftrace: Adds a marker to allow user comments

[Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

The documentation of mmiotrace describes an unimplemented feature which allows the user
to write any comments on his trace by writing on a tracing/marker file.
Here is an implementation of this idea.

It applies on last version of tip tree.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/trace.c |  264 ++++++++++++++++++++++++++++++++++++--------------
 kernel/trace/trace.h |    5 +
 2 files changed, 198 insertions(+), 71 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 1801900..ee06849 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -955,6 +955,121 @@ __trace_special(void *__tr, void *__data,
 	trace_wake_up();
 }
 
+/* Add a message provided by the user (TRACE_MARK) or by __ftrace_printk */
+
+void trace_print(char *buf, int len, struct trace_entry *tmp_ent,
+		struct trace_array *tr, struct trace_array_cpu *data,
+		unsigned long flags)
+{
+	struct trace_entry *entry;
+	int write, written = 0;
+
+	__raw_spin_lock(&data->lock);
+	entry = tracing_get_trace_entry(tr, data);
+	tracing_generic_entry_update(entry, flags);
+	entry->type = tmp_ent->type;
+
+	if (entry->type == TRACE_PRINT)
+		entry->field.print.ip = tmp_ent->field.print.ip;
+
+	write = min(len, (int)(TRACE_PRINT_BUF_SIZE-1));
+	memcpy(&entry->field.print.buf, 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, buf+written, write);
+		entry->cont.buf[write] = 0;
+		written += write;
+	}
+	__raw_spin_unlock(&data->lock);
+}
+
+/* Add a message provided by the user towards the tracing_mark file */
+int tracing_mark(char *buf, int size)
+{
+	struct trace_array *tr = &global_trace;
+	struct trace_array_cpu *data;
+	struct trace_entry tmp_ent;
+	unsigned long flags;
+	long disabled;
+	int cpu;
+
+	local_irq_save(flags);
+	cpu = raw_smp_processor_id();
+	data = tr->data[cpu];
+	disabled = atomic_inc_return(&data->disabled);
+
+	if (unlikely(disabled != 1))
+		goto out;
+
+	size = min(size, TRACE_BUF_SIZE - 1);
+	tmp_ent.type = TRACE_MARK;
+	buf[size - 1] = 0;
+
+	trace_print(buf, size, &tmp_ent, tr, data, flags);
+
+out:
+	atomic_dec(&data->disabled);
+	local_irq_restore(flags);
+	return size;
+}
+
+
+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 tmp_ent;
+	unsigned long flags;
+	long disabled;
+	va_list ap;
+	int cpu, len = 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;
+
+	tmp_ent.type = TRACE_PRINT;
+	tmp_ent.field.print.ip = ip;
+
+	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;
+
+	trace_print(trace_buf, len, &tmp_ent, tr, data, flags);
+
+	spin_unlock(&trace_buf_lock);
+
+ out:
+	atomic_dec(&data->disabled);
+	local_irq_restore(flags);
+
+	return len;
+}
+EXPORT_SYMBOL_GPL(__ftrace_printk);
+
 void
 tracing_sched_switch_trace(struct trace_array *tr,
 			   struct trace_array_cpu *data,
@@ -1943,6 +2058,26 @@ static int print_bin_fmt(struct trace_iterator *iter)
 	return 1;
 }
 
+/* Add the user message on the pipe */
+static int print_mark(struct trace_iterator *iter)
+{
+	struct trace_seq *s = &iter->seq;
+	struct trace_entry *entry = iter->ent;
+	struct trace_field *field = &entry->field;
+
+	int ret;
+
+	ret = trace_seq_printf(s, field->print.buf);
+	if (field->flags && TRACE_FLAG_CONT)
+		trace_seq_print_cont(s, iter);
+	trace_seq_printf(s, "\n");
+
+	if (ret)
+		return 1;
+	return 0;
+}
+
+
 static int trace_empty(struct trace_iterator *iter)
 {
 	struct trace_array_cpu *data;
@@ -1961,6 +2096,9 @@ static int trace_empty(struct trace_iterator *iter)
 
 static int print_trace_line(struct trace_iterator *iter)
 {
+	if (iter->ent->type == TRACE_MARK)
+		return print_mark(iter);
+
 	if (iter->trace && iter->trace->print_line)
 		return iter->trace->print_line(iter);
 
@@ -2918,6 +3056,49 @@ tracing_entries_write(struct file *filp, const char __user *ubuf,
 	return cnt;
 }
 
+static int tracing_open_mark(struct inode *inode, struct file *filp)
+{
+	int ret;
+
+	ret = tracing_open_generic(inode, filp);
+	if (ret)
+		return ret;
+
+	if (current_trace == &no_tracer)
+		return -ENODEV;
+
+	return 0;
+}
+
+
+static ssize_t
+tracing_mark_write(struct file *filp, const char __user *ubuf,
+		size_t cnt, loff_t *fpos)
+{
+	char *buf;
+
+	if (cnt > TRACE_BUF_SIZE)
+		cnt = TRACE_BUF_SIZE;
+
+	buf = kmalloc(cnt, GFP_KERNEL);
+
+	if (buf == NULL)
+		return -ENOMEM;
+
+	if (copy_from_user(buf, ubuf, cnt)) {
+		kfree(buf);
+		return -EFAULT;
+	}
+
+	cnt = tracing_mark(buf, cnt);
+	kfree(buf);
+	*fpos += cnt;
+
+	return cnt;
+}
+
+
+
 static struct file_operations tracing_max_lat_fops = {
 	.open		= tracing_open_generic,
 	.read		= tracing_max_lat_read,
@@ -2949,6 +3130,11 @@ static struct file_operations tracing_entries_fops = {
 	.write		= tracing_entries_write,
 };
 
+static struct file_operations tracing_mark_fops = {
+	.open		= tracing_open_mark,
+	.write		= tracing_mark_write,
+};
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 static ssize_t
@@ -3066,6 +3252,13 @@ static __init void tracer_init_debugfs(void)
 		pr_warning("Could not create debugfs "
 			   "'trace_entries' entry\n");
 
+	entry = debugfs_create_file("trace_marker", 0220, d_tracer,
+				    NULL, &tracing_mark_fops);
+
+	if (!entry)
+		pr_warning("Could not create debugfs "
+			   "'trace_marker' entry\n");
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 	entry = debugfs_create_file("dyn_ftrace_total_info", 0444, d_tracer,
 				    &ftrace_update_tot_cnt,
@@ -3079,77 +3272,6 @@ static __init void tracer_init_debugfs(void)
 #endif
 }
 
-#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)
-
-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_panic_handler(struct notifier_block *this,
 			       unsigned long event, void *unused)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 50b6d7a..ccc245c 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -14,6 +14,7 @@ enum trace_type {
 	TRACE_CTX,
 	TRACE_WAKE,
 	TRACE_CONT,
+	TRACE_MARK,
 	TRACE_STACK,
 	TRACE_PRINT,
 	TRACE_SPECIAL,
@@ -106,6 +107,10 @@ struct trace_entry {
 };
 
 #define TRACE_ENTRY_SIZE	sizeof(struct trace_entry)
+#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)
 
 /*
  * The CPU trace array - it consists of thousands of trace entries

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> The documentation of mmiotrace describes an unimplemented feature 
> which allows the user to write any comments on his trace by writing on 
> a tracing/marker file. Here is an implementation of this idea.
> 
> It applies on last version of tip tree.

hmm ... have you looked at the (recently implemented) ftrace_printk() 
facility?

	Ingo

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/8/25 Ingo Molnar <mingo@elte.hu>:
>
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
>
>> The documentation of mmiotrace describes an unimplemented feature
>> which allows the user to write any comments on his trace by writing on
>> a tracing/marker file. Here is an implementation of this idea.
>>
>> It applies on last version of tip tree.
>
> hmm ... have you looked at the (recently implemented) ftrace_printk()
> facility?
>
>        Ingo
>

Yes but I didn't want to use ftrace_printk() because it needs the "ip"
parameter. User messages doesn't need this. But I reuse a part of the
code of ftrace_printk and I splitted ftrace_printk() in two parts for
this purpose: __ftrace_printk() and trace_print().
I also reused the print_entry but with a new TRACE_MARK type to make
the difference when it is time to send the entry to the pipe because
user messages don't use ip.

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Steven Rostedt]

On Mon, 25 Aug 2008, Fr?d?ric Weisbecker wrote:

> 2008/8/25 Ingo Molnar <mingo@elte.hu>:
> >
> > * Fr?d?ric Weisbecker <fweisbec@gmail.com> wrote:
> >
> >> The documentation of mmiotrace describes an unimplemented feature
> >> which allows the user to write any comments on his trace by writing on
> >> a tracing/marker file. Here is an implementation of this idea.
> >>
> >> It applies on last version of tip tree.
> >
> > hmm ... have you looked at the (recently implemented) ftrace_printk()
> > facility?
> >
> >        Ingo
> >
> 
> Yes but I didn't want to use ftrace_printk() because it needs the "ip"
> parameter. User messages doesn't need this. But I reuse a part of the
> code of ftrace_printk and I splitted ftrace_printk() in two parts for
> this purpose: __ftrace_printk() and trace_print().
> I also reused the print_entry but with a new TRACE_MARK type to make
> the difference when it is time to send the entry to the pipe because
> user messages don't use ip.


Feel free to make TRACE_CONT work for you. I coupled it a little more than 
I wanted to with the ftrace print. If you can find a nice way to make 
TRACE_CONT a bit more generic, then feel free.

-- Steve

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/8/25 Steven Rostedt <rostedt@goodmis.org>:
>
> Feel free to make TRACE_CONT work for you. I coupled it a little more than
> I wanted to with the ftrace print. If you can find a nice way to make
> TRACE_CONT a bit more generic, then feel free.
>
> -- Steve
>
>

Thanks.
But TRACE_CONT is not a problem. It is generic enough to contain parts
of a TRACE_MARK message and that's why I use it in my patch.

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/8/24 Frédéric Weisbecker <fweisbec@gmail.com>:
> The documentation of mmiotrace describes an unimplemented feature which allows the user
> to write any comments on his trace by writing on a tracing/marker file.
> Here is an implementation of this idea.
>
> It applies on last version of tip tree.
>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/trace.c |  264 ++++++++++++++++++++++++++++++++++++--------------
>  kernel/trace/trace.h |    5 +
>  2 files changed, 198 insertions(+), 71 deletions(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 1801900..ee06849 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -955,6 +955,121 @@ __trace_special(void *__tr, void *__data,
>        trace_wake_up();
>  }
>
> +/* Add a message provided by the user (TRACE_MARK) or by __ftrace_printk */
> +
> +void trace_print(char *buf, int len, struct trace_entry *tmp_ent,
> +               struct trace_array *tr, struct trace_array_cpu *data,
> +               unsigned long flags)
> +{
> +       struct trace_entry *entry;
> +       int write, written = 0;
> +
> +       __raw_spin_lock(&data->lock);
> +       entry = tracing_get_trace_entry(tr, data);
> +       tracing_generic_entry_update(entry, flags);
> +       entry->type = tmp_ent->type;
> +
> +       if (entry->type == TRACE_PRINT)
> +               entry->field.print.ip = tmp_ent->field.print.ip;
> +
> +       write = min(len, (int)(TRACE_PRINT_BUF_SIZE-1));
> +       memcpy(&entry->field.print.buf, 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, buf+written, write);
> +               entry->cont.buf[write] = 0;
> +               written += write;
> +       }
> +       __raw_spin_unlock(&data->lock);
> +}
> +
> +/* Add a message provided by the user towards the tracing_mark file */
> +int tracing_mark(char *buf, int size)
> +{
> +       struct trace_array *tr = &global_trace;
> +       struct trace_array_cpu *data;
> +       struct trace_entry tmp_ent;
> +       unsigned long flags;
> +       long disabled;
> +       int cpu;
> +
> +       local_irq_save(flags);
> +       cpu = raw_smp_processor_id();
> +       data = tr->data[cpu];
> +       disabled = atomic_inc_return(&data->disabled);
> +
> +       if (unlikely(disabled != 1))
> +               goto out;
> +
> +       size = min(size, TRACE_BUF_SIZE - 1);
> +       tmp_ent.type = TRACE_MARK;
> +       buf[size - 1] = 0;
> +
> +       trace_print(buf, size, &tmp_ent, tr, data, flags);
> +
> +out:
> +       atomic_dec(&data->disabled);
> +       local_irq_restore(flags);
> +       return size;
> +}
> +
> +
> +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 tmp_ent;
> +       unsigned long flags;
> +       long disabled;
> +       va_list ap;
> +       int cpu, len = 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;
> +
> +       tmp_ent.type = TRACE_PRINT;
> +       tmp_ent.field.print.ip = ip;
> +
> +       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;
> +
> +       trace_print(trace_buf, len, &tmp_ent, tr, data, flags);
> +
> +       spin_unlock(&trace_buf_lock);
> +
> + out:
> +       atomic_dec(&data->disabled);
> +       local_irq_restore(flags);
> +
> +       return len;
> +}
> +EXPORT_SYMBOL_GPL(__ftrace_printk);
> +
>  void
>  tracing_sched_switch_trace(struct trace_array *tr,
>                           struct trace_array_cpu *data,
> @@ -1943,6 +2058,26 @@ static int print_bin_fmt(struct trace_iterator *iter)
>        return 1;
>  }
>
> +/* Add the user message on the pipe */
> +static int print_mark(struct trace_iterator *iter)
> +{
> +       struct trace_seq *s = &iter->seq;
> +       struct trace_entry *entry = iter->ent;
> +       struct trace_field *field = &entry->field;
> +
> +       int ret;
> +
> +       ret = trace_seq_printf(s, field->print.buf);
> +       if (field->flags && TRACE_FLAG_CONT)
> +               trace_seq_print_cont(s, iter);
> +       trace_seq_printf(s, "\n");
> +
> +       if (ret)
> +               return 1;
> +       return 0;
> +}
> +
> +
>  static int trace_empty(struct trace_iterator *iter)
>  {
>        struct trace_array_cpu *data;
> @@ -1961,6 +2096,9 @@ static int trace_empty(struct trace_iterator *iter)
>
>  static int print_trace_line(struct trace_iterator *iter)
>  {
> +       if (iter->ent->type == TRACE_MARK)
> +               return print_mark(iter);
> +
>        if (iter->trace && iter->trace->print_line)
>                return iter->trace->print_line(iter);
>
> @@ -2918,6 +3056,49 @@ tracing_entries_write(struct file *filp, const char __user *ubuf,
>        return cnt;
>  }
>
> +static int tracing_open_mark(struct inode *inode, struct file *filp)
> +{
> +       int ret;
> +
> +       ret = tracing_open_generic(inode, filp);
> +       if (ret)
> +               return ret;
> +
> +       if (current_trace == &no_tracer)
> +               return -ENODEV;
> +
> +       return 0;
> +}
> +
> +
> +static ssize_t
> +tracing_mark_write(struct file *filp, const char __user *ubuf,
> +               size_t cnt, loff_t *fpos)
> +{
> +       char *buf;
> +
> +       if (cnt > TRACE_BUF_SIZE)
> +               cnt = TRACE_BUF_SIZE;
> +
> +       buf = kmalloc(cnt, GFP_KERNEL);
> +
> +       if (buf == NULL)
> +               return -ENOMEM;
> +
> +       if (copy_from_user(buf, ubuf, cnt)) {
> +               kfree(buf);
> +               return -EFAULT;
> +       }
> +
> +       cnt = tracing_mark(buf, cnt);
> +       kfree(buf);
> +       *fpos += cnt;
> +
> +       return cnt;
> +}
> +
> +
> +
>  static struct file_operations tracing_max_lat_fops = {
>        .open           = tracing_open_generic,
>        .read           = tracing_max_lat_read,
> @@ -2949,6 +3130,11 @@ static struct file_operations tracing_entries_fops = {
>        .write          = tracing_entries_write,
>  };
>
> +static struct file_operations tracing_mark_fops = {
> +       .open           = tracing_open_mark,
> +       .write          = tracing_mark_write,
> +};
> +
>  #ifdef CONFIG_DYNAMIC_FTRACE
>
>  static ssize_t
> @@ -3066,6 +3252,13 @@ static __init void tracer_init_debugfs(void)
>                pr_warning("Could not create debugfs "
>                           "'trace_entries' entry\n");
>
> +       entry = debugfs_create_file("trace_marker", 0220, d_tracer,
> +                                   NULL, &tracing_mark_fops);
> +
> +       if (!entry)
> +               pr_warning("Could not create debugfs "
> +                          "'trace_marker' entry\n");
> +
>  #ifdef CONFIG_DYNAMIC_FTRACE
>        entry = debugfs_create_file("dyn_ftrace_total_info", 0444, d_tracer,
>                                    &ftrace_update_tot_cnt,
> @@ -3079,77 +3272,6 @@ static __init void tracer_init_debugfs(void)
>  #endif
>  }
>
> -#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)
> -
> -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_panic_handler(struct notifier_block *this,
>                               unsigned long event, void *unused)
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 50b6d7a..ccc245c 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -14,6 +14,7 @@ enum trace_type {
>        TRACE_CTX,
>        TRACE_WAKE,
>        TRACE_CONT,
> +       TRACE_MARK,
>        TRACE_STACK,
>        TRACE_PRINT,
>        TRACE_SPECIAL,
> @@ -106,6 +107,10 @@ struct trace_entry {
>  };
>
>  #define TRACE_ENTRY_SIZE       sizeof(struct trace_entry)
> +#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)
>
>  /*
>  * The CPU trace array - it consists of thousands of trace entries
>

Do you think I should modify something or use a way to make it better?
(Added Pekka Paalanen in Cc since it concerns an idea from his
mmiotrace's documentation)...

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

Nice to hear from you, Frédéric!

I have some comments in the following.

On Wed, 27 Aug 2008 10:59:33 +0100
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/8/24 Frédéric Weisbecker <fweisbec@gmail.com>:
> > The documentation of mmiotrace describes an unimplemented feature which allows the user
> > to write any comments on his trace by writing on a tracing/marker file.
> > Here is an implementation of this idea.
> >
> > It applies on last version of tip tree.
> >
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > ---
> >  kernel/trace/trace.c |  264 ++++++++++++++++++++++++++++++++++++--------------
> >  kernel/trace/trace.h |    5 +
> >  2 files changed, 198 insertions(+), 71 deletions(-)
> >
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index 1801900..ee06849 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -955,6 +955,121 @@ __trace_special(void *__tr, void *__data,
> >        trace_wake_up();
> >  }
> >
> > +/* Add a message provided by the user (TRACE_MARK) or by __ftrace_printk */
> > +
> > +void trace_print(char *buf, int len, struct trace_entry *tmp_ent,
> > +               struct trace_array *tr, struct trace_array_cpu *data,
> > +               unsigned long flags)
> > +{
> > +       struct trace_entry *entry;
> > +       int write, written = 0;
> > +
> > +       __raw_spin_lock(&data->lock);
> > +       entry = tracing_get_trace_entry(tr, data);
> > +       tracing_generic_entry_update(entry, flags);
> > +       entry->type = tmp_ent->type;
> > +
> > +       if (entry->type == TRACE_PRINT)
> > +               entry->field.print.ip = tmp_ent->field.print.ip;
> > +
> > +       write = min(len, (int)(TRACE_PRINT_BUF_SIZE-1));
> > +       memcpy(&entry->field.print.buf, 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, buf+written, write);
> > +               entry->cont.buf[write] = 0;
> > +               written += write;
> > +       }
> > +       __raw_spin_unlock(&data->lock);
> > +}
> > +
> > +/* Add a message provided by the user towards the tracing_mark file */
> > +int tracing_mark(char *buf, int size)
> > +{
> > +       struct trace_array *tr = &global_trace;
> > +       struct trace_array_cpu *data;
> > +       struct trace_entry tmp_ent;
> > +       unsigned long flags;
> > +       long disabled;
> > +       int cpu;
> > +
> > +       local_irq_save(flags);
> > +       cpu = raw_smp_processor_id();
> > +       data = tr->data[cpu];
> > +       disabled = atomic_inc_return(&data->disabled);
> > +
> > +       if (unlikely(disabled != 1))
> > +               goto out;
> > +
> > +       size = min(size, TRACE_BUF_SIZE - 1);
> > +       tmp_ent.type = TRACE_MARK;
> > +       buf[size - 1] = 0;
> > +
> > +       trace_print(buf, size, &tmp_ent, tr, data, flags);
> > +
> > +out:
> > +       atomic_dec(&data->disabled);
> > +       local_irq_restore(flags);
> > +       return size;
> > +}

IMHO we could just make ftrace_printk() work for all tracers. I doubt
there will be need to be able to record nil bytes. The idea of a marker
is to be a line of human readable text.

> > +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 tmp_ent;
> > +       unsigned long flags;
> > +       long disabled;
> > +       va_list ap;
> > +       int cpu, len = 0;
> > +
> > +       if (likely(!ftrace_function_enabled))
> > +               return 0;

And that is the kind of check that makes current ftrace_printk() unusable.
I think this restriction should be lifted and allow it to work on all
tracers. I would also like to be able to have e.g. mmiotrace_marker(),
which would have the same signature as ftrace_printk(), but is a no-op if
mmiotrace is not active. So, we could have an __ftrace_vprintk() to make
writing such wrappers easy. And the wrappers could be #ifdef'd away, if
the corresponding tracer is not built.

I recall somewhere mentioning, that one shouldn't leave ftrace_printk's
lying around in "final" code, so I'm not sure how people feel about this
wrapping idea, especially when e.g. mmiotrace is hoped to be built-in by
default. OTOH, I don't think in-tree drivers and stuff want to use them,
so they would be mostly offered for out-of-tree modules
(reverse-engineering) and developers (debugging). That makes me wonder
if they would be accepted (as exported symbols).

> > +
> > +       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;
> > +
> > +       tmp_ent.type = TRACE_PRINT;
> > +       tmp_ent.field.print.ip = ip;
> > +
> > +       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;
> > +
> > +       trace_print(trace_buf, len, &tmp_ent, tr, data, flags);
> > +
> > +       spin_unlock(&trace_buf_lock);
> > +
> > + out:
> > +       atomic_dec(&data->disabled);
> > +       local_irq_restore(flags);
> > +
> > +       return len;
> > +}
> > +EXPORT_SYMBOL_GPL(__ftrace_printk);
> > +
> >  void
> >  tracing_sched_switch_trace(struct trace_array *tr,
> >                           struct trace_array_cpu *data,
> > @@ -1943,6 +2058,26 @@ static int print_bin_fmt(struct trace_iterator *iter)
> >        return 1;
> >  }
> >
> > +/* Add the user message on the pipe */
> > +static int print_mark(struct trace_iterator *iter)
> > +{
> > +       struct trace_seq *s = &iter->seq;
> > +       struct trace_entry *entry = iter->ent;
> > +       struct trace_field *field = &entry->field;
> > +
> > +       int ret;
> > +
> > +       ret = trace_seq_printf(s, field->print.buf);
> > +       if (field->flags && TRACE_FLAG_CONT)
> > +               trace_seq_print_cont(s, iter);
> > +       trace_seq_printf(s, "\n");
> > +
> > +       if (ret)
> > +               return 1;
> > +       return 0;
> > +}
> > +
> > +
> >  static int trace_empty(struct trace_iterator *iter)
> >  {
> >        struct trace_array_cpu *data;
> > @@ -1961,6 +2096,9 @@ static int trace_empty(struct trace_iterator *iter)
> >
> >  static int print_trace_line(struct trace_iterator *iter)
> >  {
> > +       if (iter->ent->type == TRACE_MARK)
> > +               return print_mark(iter);
> > +

Please, put this call after the following...

> >        if (iter->trace && iter->trace->print_line)
> >                return iter->trace->print_line(iter);

..so that tracers may override it at will. Mmiotrace needs to replace
newlines and nil characters, before printing it in its own style, i.e.
prefixed with a tag and a timestamp, which are specified in the mmiotrace
log format.

> >
> > @@ -2918,6 +3056,49 @@ tracing_entries_write(struct file *filp, const char __user *ubuf,
> >        return cnt;
> >  }
> >
> > +static int tracing_open_mark(struct inode *inode, struct file *filp)
> > +{
> > +       int ret;
> > +
> > +       ret = tracing_open_generic(inode, filp);
> > +       if (ret)
> > +               return ret;
> > +
> > +       if (current_trace == &no_tracer)
> > +               return -ENODEV;
> > +
> > +       return 0;
> > +}
> > +
> > +
> > +static ssize_t
> > +tracing_mark_write(struct file *filp, const char __user *ubuf,
> > +               size_t cnt, loff_t *fpos)
> > +{
> > +       char *buf;
> > +
> > +       if (cnt > TRACE_BUF_SIZE)
> > +               cnt = TRACE_BUF_SIZE;
> > +
> > +       buf = kmalloc(cnt, GFP_KERNEL);
> > +
> > +       if (buf == NULL)
> > +               return -ENOMEM;
> > +
> > +       if (copy_from_user(buf, ubuf, cnt)) {
> > +               kfree(buf);
> > +               return -EFAULT;
> > +       }
> > +
> > +       cnt = tracing_mark(buf, cnt);
> > +       kfree(buf);
> > +       *fpos += cnt;
> > +
> > +       return cnt;
> > +}
> > +
> > +
> > +
> >  static struct file_operations tracing_max_lat_fops = {
> >        .open           = tracing_open_generic,
> >        .read           = tracing_max_lat_read,
> > @@ -2949,6 +3130,11 @@ static struct file_operations tracing_entries_fops = {
> >        .write          = tracing_entries_write,
> >  };
> >
> > +static struct file_operations tracing_mark_fops = {
> > +       .open           = tracing_open_mark,
> > +       .write          = tracing_mark_write,
> > +};
> > +
> >  #ifdef CONFIG_DYNAMIC_FTRACE
> >
> >  static ssize_t
> > @@ -3066,6 +3252,13 @@ static __init void tracer_init_debugfs(void)
> >                pr_warning("Could not create debugfs "
> >                           "'trace_entries' entry\n");
> >
> > +       entry = debugfs_create_file("trace_marker", 0220, d_tracer,
> > +                                   NULL, &tracing_mark_fops);
> > +
> > +       if (!entry)
> > +               pr_warning("Could not create debugfs "
> > +                          "'trace_marker' entry\n");
> > +
> >  #ifdef CONFIG_DYNAMIC_FTRACE
> >        entry = debugfs_create_file("dyn_ftrace_total_info", 0444, d_tracer,
> >                                    &ftrace_update_tot_cnt,
> > @@ -3079,77 +3272,6 @@ static __init void tracer_init_debugfs(void)
> >  #endif
> >  }
> >
> > -#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)
> > -
> > -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_panic_handler(struct notifier_block *this,
> >                               unsigned long event, void *unused)
> > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > index 50b6d7a..ccc245c 100644
> > --- a/kernel/trace/trace.h
> > +++ b/kernel/trace/trace.h
> > @@ -14,6 +14,7 @@ enum trace_type {
> >        TRACE_CTX,
> >        TRACE_WAKE,
> >        TRACE_CONT,
> > +       TRACE_MARK,
> >        TRACE_STACK,
> >        TRACE_PRINT,

I think TRACE_MARK and TRACE_PRINT are equivalent, so we could stick
to TRACE_PRINT.

> >        TRACE_SPECIAL,
> > @@ -106,6 +107,10 @@ struct trace_entry {
> >  };
> >
> >  #define TRACE_ENTRY_SIZE       sizeof(struct trace_entry)
> > +#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)
> >
> >  /*
> >  * The CPU trace array - it consists of thousands of trace entries
> >
> 
> Do you think I should modify something or use a way to make it better?
> (Added Pekka Paalanen in Cc since it concerns an idea from his
> mmiotrace's documentation)...

Thanks for adding me, I've been brewing my own version of this stuff,
but didn't yet solve the __ftrace_printk-is-unusable issue yet.
I have the mmiotrace specific parts written for TRACE_PRINT, so we haven't
really overlapped each other's work yet.

Ingo recently told me it would be good to have a generic debugfs file
for adding markers to any tracer log, and this is basically what you did.

I didn't try the patch yet, or read it too carefully, but I should.
Unfortunately I'm away the next weekend, so I hope to continue working
on it the weekend after that.


Thanks,
pq

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Ingo Molnar]

* Pekka Paalanen <pq@iki.fi> wrote:

> > Do you think I should modify something or use a way to make it 
> > better? (Added Pekka Paalanen in Cc since it concerns an idea from 
> > his mmiotrace's documentation)...
> 
> Thanks for adding me, I've been brewing my own version of this stuff, 
> but didn't yet solve the __ftrace_printk-is-unusable issue yet. I have 
> the mmiotrace specific parts written for TRACE_PRINT, so we haven't 
> really overlapped each other's work yet.

we can certainly include and test Frédéric's patch in tip/tracing/ftrace 
- i'll wait for v2 as i guess he will implement the modifications 
suggested by you?

	Ingo

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

Hello Pekka,

2008/8/27 Pekka Paalanen <pq@iki.fi>:
> IMHO we could just make ftrace_printk() work for all tracers. I doubt
> there will be need to be able to record nil bytes. The idea of a marker
> is to be a line of human readable text.
>
>> > +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 tmp_ent;
>> > +       unsigned long flags;
>> > +       long disabled;
>> > +       va_list ap;
>> > +       int cpu, len = 0;
>> > +
>> > +       if (likely(!ftrace_function_enabled))
>> > +               return 0;
>
> And that is the kind of check that makes current ftrace_printk() unusable.
> I think this restriction should be lifted and allow it to work on all
> tracers. I would also like to be able to have e.g. mmiotrace_marker(),
> which would have the same signature as ftrace_printk(), but is a no-op if
> mmiotrace is not active. So, we could have an __ftrace_vprintk() to make
> writing such wrappers easy. And the wrappers could be #ifdef'd away, if
> the corresponding tracer is not built.

I like your idea of a ftrace_vprintk wrapper.
But actually I'm questioning about the fact that the tracing api
itself is not generic enough.

At this time, a tracer has to put a function inside the tracing api
when it wants to add an entry into the list.
See __trace_mmiotrace_rw() for example.

Just imagine if one wants to implement a tracer by using a simple module.
The way seems to be simple at the beginning: you define your struct
tracer, implement your functions and register your tracer.
But the simple, single function that will add your entries has to be
put in tracing api.
It's quite impossible without changing the trace.c file and so
impossible without recompiling your kernel.

And if I make my own tracer and want to implement my handler for the
marker messages, I will have to put my foo_trace_printk in trace.c and
add it on the wrapper.

IMHO the choice of a wrapper is good but it should dynamically
dispatch the message on a handler proposed by the tracer. I think
about a new function pointer which could be called "mark" on the
struct tracer.

And (always IMHO) I think that functions like __trace_mmiotrace_rw()
shouldn't be located on trace.c but implemented on the appropriate
tracer (in this example: trace_mmiotrace.c).
And for this purpose, functions like tracing_generic_entry_update()
(or even more higher level function of entry adding) should be
symbol's exported.

With such a new environment, building personal and quick tracers by
using modules may be more appreciated if one has not to touch the
tracing API or the whole running kernel.

> I recall somewhere mentioning, that one shouldn't leave ftrace_printk's
> lying around in "final" code, so I'm not sure how people feel about this
> wrapping idea, especially when e.g. mmiotrace is hoped to be built-in by
> default. OTOH, I don't think in-tree drivers and stuff want to use them,
> so they would be mostly offered for out-of-tree modules
> (reverse-engineering) and developers (debugging). That makes me wonder
> if they would be accepted (as exported symbols).

Yes I think such a function should really be exported. For example
using mmiotrace on a module and beeing able to signal the fact that we
are entering the "foo" function seems to me very useful. It's
important to know where we are in all these IO for debugging....


>> >  static int print_trace_line(struct trace_iterator *iter)
>> >  {
>> > +       if (iter->ent->type == TRACE_MARK)
>> > +               return print_mark(iter);
>> > +
>
> Please, put this call after the following...
>
>> >        if (iter->trace && iter->trace->print_line)
>> >                return iter->trace->print_line(iter);
>
> ..so that tracers may override it at will. Mmiotrace needs to replace
> newlines and nil characters, before printing it in its own style, i.e.
> prefixed with a tag and a timestamp, which are specified in the mmiotrace
> log format.

Perhaps the idea of an appropriate "mark" handler for each tracer
could solve this...


> I didn't try the patch yet, or read it too carefully, but I should.
> Unfortunately I'm away the next weekend, so I hope to continue working
> on it the weekend after that.

No problem.

Thanks!

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/8/28 Ingo Molnar <mingo@elte.hu>:
>
> * Pekka Paalanen <pq@iki.fi> wrote:
>
>> > Do you think I should modify something or use a way to make it
>> > better? (Added Pekka Paalanen in Cc since it concerns an idea from
>> > his mmiotrace's documentation)...
>>
>> Thanks for adding me, I've been brewing my own version of this stuff,
>> but didn't yet solve the __ftrace_printk-is-unusable issue yet. I have
>> the mmiotrace specific parts written for TRACE_PRINT, so we haven't
>> really overlapped each other's work yet.
>
> we can certainly include and test Frédéric's patch in tip/tracing/ftrace
> - i'll wait for v2 as i guess he will implement the modifications
> suggested by you?
>
>        Ingo

Ok I will send a new patch on the next days...

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

On Thu, 28 Aug 2008 11:04:36 +0100
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/8/27 Pekka Paalanen <pq@iki.fi>:
> >
> > tracers. I would also like to be able to have e.g. mmiotrace_marker(),
> > which would have the same signature as ftrace_printk(), but is a no-op if
> > mmiotrace is not active. So, we could have an __ftrace_vprintk() to make
> > writing such wrappers easy. And the wrappers could be #ifdef'd away, if
> > the corresponding tracer is not built.
> 
> I like your idea of a ftrace_vprintk wrapper.
> But actually I'm questioning about the fact that the tracing api
> itself is not generic enough.

I think making it more modular would be nice, but I'm not really working
on the generic parts.

> And (always IMHO) I think that functions like __trace_mmiotrace_rw()
> shouldn't be located on trace.c but implemented on the appropriate
> tracer (in this example: trace_mmiotrace.c).

I feel the same.

> > I recall somewhere mentioning, that one shouldn't leave ftrace_printk's
> > lying around in "final" code, so I'm not sure how people feel about this
> > wrapping idea, especially when e.g. mmiotrace is hoped to be built-in by
> > default. OTOH, I don't think in-tree drivers and stuff want to use them,
> > so they would be mostly offered for out-of-tree modules
> > (reverse-engineering) and developers (debugging). That makes me wonder
> > if they would be accepted (as exported symbols).
> 
> Yes I think such a function should really be exported. For example
> using mmiotrace on a module and beeing able to signal the fact that we
> are entering the "foo" function seems to me very useful. It's
> important to know where we are in all these IO for debugging....

Yes, but the atmosphere is that if there are no users in-tree, the feature
gets kicked, out-of-tree users or no. That's the reason mmiotrace went
in-tree in the first place. So, to get that stuff exported, we might need
in-tree users, I believe.


Thanks.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/8/28 Pekka Paalanen <pq@iki.fi>:
> Yes, but the atmosphere is that if there are no users in-tree, the feature
> gets kicked, out-of-tree users or no. That's the reason mmiotrace went
> in-tree in the first place. So, to get that stuff exported, we might need
> in-tree users, I believe.

Perhaps it should be more discussed because it is an unsual case...

Ok so just a question before I start a new patch to correct the marker's file.

What is the best way to implement tracers's printk handlers?
Do you think that these functions must be implemented in trace.c or is
it more relevant to dispatch the message to
a function provided by the current tracer in its struct tracer
operations? If such handler is not implemented, we just defaults the
formatting like ftrace_printk does.

Thanks...

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

On Thu, 4 Sep 2008 18:20:09 +0200
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> What is the best way to implement tracers's printk handlers?

Your last message had an idea I didn't think before (or I misunderstood
you), that there could be an optional callback for inserting markers
into the ring buffer. My first thought was to have the usual entry
handler (print_line callback) to format marker text when it is taken
from the ring buffer and read to user space.

> Do you think that these functions must be implemented in trace.c or is
> it more relevant to dispatch the message to
> a function provided by the current tracer in its struct tracer
> operations? If such handler is not implemented, we just defaults the
> formatting like ftrace_printk does.

For the output formatting case, I'd prefer the print_line callback,
it's just one more case for an entry type in there. Notice the
difference between writing to ring buffer and reading to user.

The trick is, when does mmiotrace sanitize the marker text, when it
comes from user space, the debugfs file. Either
a) have another callback for inserting messages into the ring buffer
b) have a customisable trace_seq_print_cont()

I think I'd favour b). When I tried to use trace_seq_print_cont(),
I found it difficult to control the printing of \n at the end of
message. So I would implement my own routine to handle also what
trace_seq_print_cont() does, filtering the text while copying it
to struct trace_seq. I'm not sure where this function should live.
It could be useful to all tracers, that want "one line per marker
entry" style output, so it could live in trace.c.

So my suggestion is to put the marker text unfiltered into the ring
buffer, and filter it (if required) during read to user (print_line).


Cheers,
pq

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Steven Rostedt]

On Thu, 4 Sep 2008, Pekka Paalanen wrote:

> On Thu, 4 Sep 2008 18:20:09 +0200
> "Fr?d?ric Weisbecker" <fweisbec@gmail.com> wrote:
> 
> > What is the best way to implement tracers's printk handlers?
> 
> Your last message had an idea I didn't think before (or I misunderstood
> you), that there could be an optional callback for inserting markers
> into the ring buffer. My first thought was to have the usual entry
> handler (print_line callback) to format marker text when it is taken
> from the ring buffer and read to user space.
> 
> > Do you think that these functions must be implemented in trace.c or is
> > it more relevant to dispatch the message to
> > a function provided by the current tracer in its struct tracer
> > operations? If such handler is not implemented, we just defaults the
> > formatting like ftrace_printk does.
> 
> For the output formatting case, I'd prefer the print_line callback,
> it's just one more case for an entry type in there. Notice the
> difference between writing to ring buffer and reading to user.
> 
> The trick is, when does mmiotrace sanitize the marker text, when it
> comes from user space, the debugfs file. Either
> a) have another callback for inserting messages into the ring buffer
> b) have a customisable trace_seq_print_cont()
> 
> I think I'd favour b). When I tried to use trace_seq_print_cont(),
> I found it difficult to control the printing of \n at the end of
> message. So I would implement my own routine to handle also what
> trace_seq_print_cont() does, filtering the text while copying it
> to struct trace_seq. I'm not sure where this function should live.
> It could be useful to all tracers, that want "one line per marker
> entry" style output, so it could live in trace.c.
> 
> So my suggestion is to put the marker text unfiltered into the ring
> buffer, and filter it (if required) during read to user (print_line).
> 

For logdev (my pet project from way back, and the latest ftrace is based 
on), I had a CUSTOM type. The API allowed to register a callback to a 
type, and it would associate that type to some number (descriptor) and 
pass that number back to you. Then you could use this number to write to 
the buffer using the CUSTOM type and registered number. On output, when a 
CUSTOM type is detected, it would read the custom.id (the number) and 
search for any registered callbacks to handle the entry.

This probably would not be too difficult to implement. Especially since it 
is already implemented in logdev.
(see http://rostedt.homelinux.com/logdev/)

-- Steve

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Frédéric Weisbecker]

2008/9/4 Steven Rostedt <rostedt@goodmis.org>:

> For logdev (my pet project from way back, and the latest ftrace is based
> on), I had a CUSTOM type. The API allowed to register a callback to a
> type, and it would associate that type to some number (descriptor) and
> pass that number back to you. Then you could use this number to write to
> the buffer using the CUSTOM type and registered number. On output, when a
> CUSTOM type is detected, it would read the custom.id (the number) and
> search for any registered callbacks to handle the entry.
>
> This probably would not be too difficult to implement. Especially since it
> is already implemented in logdev.
> (see http://rostedt.homelinux.com/logdev/)
>
> -- Steve

Why not. It is a way for a tracer to handle output for any type of entries.
But will this feature really be used for other special types than
TRACE_PRINT? I'm not sure... If it is not the case, the Pekka's
solution seems to me far more simple.

But actually I don't know the needs of others tracers...

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

On Sat, 6 Sep 2008 13:39:55 +0200
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/9/4 Steven Rostedt <rostedt@goodmis.org>:
> 
> > For logdev (my pet project from way back, and the latest ftrace is based
> > on), I had a CUSTOM type. The API allowed to register a callback to a
> > type, and it would associate that type to some number (descriptor) and
> > pass that number back to you. Then you could use this number to write to
> > the buffer using the CUSTOM type and registered number. On output, when a
> > CUSTOM type is detected, it would read the custom.id (the number) and
> > search for any registered callbacks to handle the entry.
> >
> > This probably would not be too difficult to implement. Especially since it
> > is already implemented in logdev.
> > (see http://rostedt.homelinux.com/logdev/)
> >
> > -- Steve
> 
> Why not. It is a way for a tracer to handle output for any type of entries.
> But will this feature really be used for other special types than
> TRACE_PRINT? I'm not sure... If it is not the case, the Pekka's
> solution seems to me far more simple.
> 
> But actually I don't know the needs of others tracers...

I never thought TRACE_PRINT would need anything more. At least I'm happy
with the concept of TRACE_PRINT, it just needs some adjustments in the API
to be nice to use.

True, I might some day want to add yet another entry type for mmiotrace,
but I'm not planning that for now, and I could just add it like they are
in the current framework. But the benefit of the CUSTOM type would be
to allow modularized and out-of-tree tracers. And then, why keep the
current predefined types, why not make everything a CUSTOM type? Just
define a block size in the ring buffer and use TRACE_CONT to handle
payload larger than the block.

Anyway, personally I'm satisfied with the current state of the framework
and I can only talk for mmiotrace.


Cheers,
pq

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

Steven,

is there a logic behind trace_seq_print_cont() printing the terminating
newline only, when there actually is no TRACE_CONT entry?

Hmm, wait a minute, I don't understand how this thing works at all.

Let's take for instance print_lat_fmt() which is the first user of
trace_seq_print_cont(). Now, print_lat_fmt() does

	struct trace_entry *entry = iter->ent;

and uses 'entry'. Let's assume it is of type TRACE_PRINT. It does

	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;

Ok, it prints the beginning of the message, and if there should be
continuation blocks, it calls trace_seq_print_cont(), defined as
follows:

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);
}

Here it uses trace_entry_idx() to get 'ent'. What's the difference to
iter->ent? I don't understand how trace_entry_idx() works, but looking
at how it is used, it must return the pointer to the *next* entry in
the ring buffer. So I don't understand the name of the function, and I
don't see a call to __trace_iterator_increment(), which is confusing.

If contrary to the assumption, 'ent' is not a continuation, it prints
the terminating newline. This is an exceptional case, as the original
entry was marked as having continuation entries.

The normal case then is to execute the do-while, until it hits a
non-continuation entry. Here it does *not* print the terminating newline.

Steven, could you explain what is going on here?


Thanks.



On Thu, 4 Sep 2008 20:30:58 +0300
Pekka Paalanen <pq@iki.fi> wrote:

> b) have a customisable trace_seq_print_cont()
> 
> I think I'd favour b). When I tried to use trace_seq_print_cont(),
> I found it difficult to control the printing of \n at the end of
> message. So I would implement my own routine to handle also what
> trace_seq_print_cont() does, filtering the text while copying it
> to struct trace_seq. I'm not sure where this function should live.
> It could be useful to all tracers, that want "one line per marker
> entry" style output, so it could live in trace.c.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Steven Rostedt]

On Sun, 7 Sep 2008, Pekka Paalanen wrote:

> Steven,
> 
> is there a logic behind trace_seq_print_cont() printing the terminating
> newline only, when there actually is no TRACE_CONT entry?

Actually, that case is more of an anomaly than the correct. It means
that somehow the print statement wanted to continue, but did not. This 
means that the print statement probably did not finish the line, and
that we should do a newline to make sure the next entry starts on a
new line.

> 
> Hmm, wait a minute, I don't understand how this thing works at all.

Heh, I guess I need to add more comments :-/

> 
> Let's take for instance print_lat_fmt() which is the first user of
> trace_seq_print_cont(). Now, print_lat_fmt() does
> 
> 	struct trace_entry *entry = iter->ent;

iter->ent is the start of the entry to print. It is not necessarily
the current entry in the iteration buffer.

> 
> and uses 'entry'. Let's assume it is of type TRACE_PRINT. It does
> 
> 	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;
> 
> Ok, it prints the beginning of the message, and if there should be
> continuation blocks, it calls trace_seq_print_cont(), defined as
> follows:
> 
> 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);
> }

Because we do a merge sort of the entries in each CPU buffer, after we
get the next entry to print, we increment that iteration buffer. This
means that trace_entry_idx() will return the next entry field after
we got the iter->ent. This is also why we use iter->ent instead of
just calling trace_entry_idx. This keeps the merge sort simpler.

> 
> Here it uses trace_entry_idx() to get 'ent'. What's the difference to
> iter->ent? I don't understand how trace_entry_idx() works, but looking
> at how it is used, it must return the pointer to the *next* entry in
> the ring buffer. So I don't understand the name of the function, and I
> don't see a call to __trace_iterator_increment(), which is confusing.

iter->ent is the entry to be used in the "show" function. When we found 
that entry, we incremented the buffer to get it ready for the next
merge sort.

When we get to show, iter->ent is the entry to print, and if we use
iter_entry_idx() that will point to the next entry in that buffer that
will be used next time. I also did this to make it easier for the latency 
format be able to calculate the notations (like the '!').

> 
> If contrary to the assumption, 'ent' is not a continuation, it prints
> the terminating newline. This is an exceptional case, as the original
> entry was marked as having continuation entries.

Right, this is somehow an entry was flagged as continue, but it did not.
It is probably a bug in the code, and instead of writing a strange format,
where the next entry continued on the same line, I chose to let the
entry go onto the next line.

> 
> The normal case then is to execute the do-while, until it hits a
> non-continuation entry. Here it does *not* print the terminating newline.

Correct. The reason is that the ftrace_printk() call should have contained
its own new line. I could also add a check (and probably will) to see if
the printk did end with a newline, and add one if it did not.

> 
> Steven, could you explain what is going on here?

Just did ;-)

Hope it helps,

-- Steve

Re: [Patch] Tracing/ftrace: Adds a marker to allow user comments

[Pekka Paalanen]

On Sun, 7 Sep 2008 13:29:40 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Sun, 7 Sep 2008, Pekka Paalanen wrote:
> 
> > Steven,
> > 
> > is there a logic behind trace_seq_print_cont() printing the terminating
> > newline only, when there actually is no TRACE_CONT entry?
> 
> Actually, that case is more of an anomaly than the correct. It means
> that somehow the print statement wanted to continue, but did not. This 
> means that the print statement probably did not finish the line, and
> that we should do a newline to make sure the next entry starts on a
> new line.

Oh, I never thought it from that point of view.

> > 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);
> > }
> 
> Because we do a merge sort of the entries in each CPU buffer, after we
> get the next entry to print, we increment that iteration buffer. This
> means that trace_entry_idx() will return the next entry field after
> we got the iter->ent. This is also why we use iter->ent instead of
> just calling trace_entry_idx. This keeps the merge sort simpler.

Yes, I forgot the per-cpu buffers. When merging you want the first one
wrt. timestamp, and when continuing you want the next on that cpu's
buffer.

> > Here it uses trace_entry_idx() to get 'ent'. What's the difference to
> > iter->ent? I don't understand how trace_entry_idx() works, but looking
> > at how it is used, it must return the pointer to the *next* entry in
> > the ring buffer. So I don't understand the name of the function, and I
> > don't see a call to __trace_iterator_increment(), which is confusing.
> 
> iter->ent is the entry to be used in the "show" function. When we found 
> that entry, we incremented the buffer to get it ready for the next
> merge sort.
> 
> When we get to show, iter->ent is the entry to print, and if we use
> iter_entry_idx() that will point to the next entry in that buffer that
> will be used next time. I also did this to make it easier for the latency 
> format be able to calculate the notations (like the '!').
> 
> > If contrary to the assumption, 'ent' is not a continuation, it prints
> > the terminating newline. This is an exceptional case, as the original
> > entry was marked as having continuation entries.
> 
> Right, this is somehow an entry was flagged as continue, but it did not.
> It is probably a bug in the code, and instead of writing a strange format,
> where the next entry continued on the same line, I chose to let the
> entry go onto the next line.
> 
> > The normal case then is to execute the do-while, until it hits a
> > non-continuation entry. Here it does *not* print the terminating newline.
> 
> Correct. The reason is that the ftrace_printk() call should have contained
> its own new line. I could also add a check (and probably will) to see if
> the printk did end with a newline, and add one if it did not.

My first idea was to filter out all newlines from messages, making a
message a single line, and then force a newline, but now I realize
that would be an exception to the printk convention. Maybe I should
just start a new line in the output, when I get a newline :-)
Although that probably means my version of trace_seq_print_cont() must
live in trace.c, which IMHO is over-crowded already.

But then there's a small chance the whole output of a single
TRACE_PRINT entry might not fit into one trace_seq ever, since each
line in mmiotrace has a prologue. Oh well, can't win always, I'll just
drop what doesn't fit into output.

Hmm, it already does that, doesn't it, if the output does not fit into
trace_seq buffer. There might be a corner case...

> > Steven, could you explain what is going on here?
> 
> Just did ;-)
> 
> Hope it helps,

Oh yes, thank you very much :-)

btw. How do you feel about moving the #ifdef CONFIG_MMIOTRACE functions
from trace.c to trace_mmiotrace.c and unstatifying all the functions
they need? Seems some of them are inline, and the spinlock stuff just
looks so... raw :-)

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Tracing/ftrace: trouble with trace_entries and trace_pipe

[Pekka Paalanen]

Hi Steven and others,

first a minor bug: it seems the units of /debug/tracing/trace_entries
is different for read and write. This is confusing for the users, since
I can't say "if you have problems, double it". If I read from it
something like 16422, then write back 16422, next I read 214. I can't
recall the exact numbers, but the difference really is two orders of
magnitude. I have 1 GB RAM in this box, so that shouldn't be an issue.

My other problem is with trace_pipe. It is again making 'cat' quit too
early. The condition triggered is
	if (!tracer_enabled && iter->pos) {
in tracing_read_pipe(), and it is followed by triggering
        /* stop when tracing is finished */
        if (trace_empty(iter)) {
and then sret=0, so read returns 0 and 'cat' exits.

Now, I am trying my mmiotrace marker patches, but as far as I can tell,
nothing I modified is the reason for this. I didn't yet explicitly test
for it, though. I'll send these patches after I hear from Frederic.

The cat-quit problem is not a constant state. After boot, I could play
with my markers and testmmiotrace without cat quitting. Then something
happens, and cat starts the quitting behaviour, and won't get to normal
by disabling and enabling mmiotrace.

I have a couple of wild guesses of what might be related:
- ring buffer wrap-around
- ring buffer overflow (at first try I hit these, the second try
after putting debug-pr_info's in place I don't hit this)
- ring buffer resize (after playing with trace_entries, cat-quit
problem was present, though it might have been present before)

After viewing the git history, I have some more guesses, mainly
related to setting tracer_enabled to 0.
- commit 2b1bce1787700768cbc87c8509851c6f49d252dc
I don't see where tracer_enabled would be set to 1, when
mmiotrace is enabled. It used to default to 1 and mmiotrace was happy.
- __tracing_open() sets it to 0 (not called for the pipe)
- tracing_release() sets it to 1
- tracing_ctrl_write() toggles it
- tracing_read_pipe() tests it
- tracer_alloc_buffers() uses it
And other tracers seem to use it a lot.

Mmiotrace does use the tracer::ctrl_update hook, and allow/disallow
calls to __trace_mmiotrace_{rw,map}() via enabling/disabling the whole
mmiotrace core. Is this not enough, or is it inappropriate?

It seems tracer_enabled is used by the trace framework itself to
enable/disable... what? Hmm, maybe nothing I care about.

Should mmiotrace simply do
	tracer_enabled = 1;
in mmio_trace_init()?

Should mmiotrace test tracer_enabled, and if so, when?


Thanks.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: Tracing/ftrace: trouble with trace_entries and trace_pipe

[Steven Rostedt]

On Mon, 15 Sep 2008, Pekka Paalanen wrote:

> Hi Steven and others,
> 
> first a minor bug: it seems the units of /debug/tracing/trace_entries
> is different for read and write. This is confusing for the users, since
> I can't say "if you have problems, double it". If I read from it
> something like 16422, then write back 16422, next I read 214. I can't
> recall the exact numbers, but the difference really is two orders of
> magnitude. I have 1 GB RAM in this box, so that shouldn't be an issue.

You write to it the same number that you read from and it returned 
something different?? That is indeed a bug, since it should definitely 
detect that. Is this linux-tip? I'll have to play with it to make sure 
nothing broke it recently.

I just tried the latest mainline, and it seemed to work there.

> 
> My other problem is with trace_pipe. It is again making 'cat' quit too
> early. The condition triggered is
> 	if (!tracer_enabled && iter->pos) {
> in tracing_read_pipe(), and it is followed by triggering
>         /* stop when tracing is finished */
>         if (trace_empty(iter)) {
> and then sret=0, so read returns 0 and 'cat' exits.
> 
> Now, I am trying my mmiotrace marker patches, but as far as I can tell,
> nothing I modified is the reason for this. I didn't yet explicitly test
> for it, though. I'll send these patches after I hear from Frederic.
> 
> The cat-quit problem is not a constant state. After boot, I could play
> with my markers and testmmiotrace without cat quitting. Then something
> happens, and cat starts the quitting behaviour, and won't get to normal
> by disabling and enabling mmiotrace.
> 
> I have a couple of wild guesses of what might be related:
> - ring buffer wrap-around
> - ring buffer overflow (at first try I hit these, the second try
> after putting debug-pr_info's in place I don't hit this)
> - ring buffer resize (after playing with trace_entries, cat-quit
> problem was present, though it might have been present before)
> 
> After viewing the git history, I have some more guesses, mainly
> related to setting tracer_enabled to 0.
> - commit 2b1bce1787700768cbc87c8509851c6f49d252dc
> I don't see where tracer_enabled would be set to 1, when
> mmiotrace is enabled. It used to default to 1 and mmiotrace was happy.
> - __tracing_open() sets it to 0 (not called for the pipe)
> - tracing_release() sets it to 1
> - tracing_ctrl_write() toggles it
> - tracing_read_pipe() tests it
> - tracer_alloc_buffers() uses it
> And other tracers seem to use it a lot.
> 
> Mmiotrace does use the tracer::ctrl_update hook, and allow/disallow
> calls to __trace_mmiotrace_{rw,map}() via enabling/disabling the whole
> mmiotrace core. Is this not enough, or is it inappropriate?
> 
> It seems tracer_enabled is used by the trace framework itself to
> enable/disable... what? Hmm, maybe nothing I care about.
> 
> Should mmiotrace simply do
> 	tracer_enabled = 1;
> in mmio_trace_init()?
> 
> Should mmiotrace test tracer_enabled, and if so, when?

No, tracer_enabled is something that is internal to the tracer 
infrastructure. 

if you read from either tracing/trace or tracing/latency_trace it will 
disable the tracer while you dump. But you should not be doing that. The 
trace_pipe should not disable that either.

-- Steve

Re: Tracing/ftrace: trouble with trace_entries and trace_pipe

[Frédéric Weisbecker]

2008/9/15 Pekka Paalanen <pq@iki.fi>:
> My other problem is with trace_pipe. It is again making 'cat' quit too
> early. The condition triggered is
>        if (!tracer_enabled && iter->pos) {
> in tracing_read_pipe(), and it is followed by triggering
>        /* stop when tracing is finished */
>        if (trace_empty(iter)) {
> and then sret=0, so read returns 0 and 'cat' exits.
>
> Now, I am trying my mmiotrace marker patches, but as far as I can tell,
> nothing I modified is the reason for this. I didn't yet explicitly test
> for it, though. I'll send these patches after I hear from Frederic.
>
> The cat-quit problem is not a constant state. After boot, I could play
> with my markers and testmmiotrace without cat quitting. Then something
> happens, and cat starts the quitting behaviour, and won't get to normal
> by disabling and enabling mmiotrace.
>
> I have a couple of wild guesses of what might be related:
> - ring buffer wrap-around
> - ring buffer overflow (at first try I hit these, the second try
> after putting debug-pr_info's in place I don't hit this)
> - ring buffer resize (after playing with trace_entries, cat-quit
> problem was present, though it might have been present before)
>
> After viewing the git history, I have some more guesses, mainly
> related to setting tracer_enabled to 0.
> - commit 2b1bce1787700768cbc87c8509851c6f49d252dc
> I don't see where tracer_enabled would be set to 1, when
> mmiotrace is enabled. It used to default to 1 and mmiotrace was happy.
> - __tracing_open() sets it to 0 (not called for the pipe)
> - tracing_release() sets it to 1
> - tracing_ctrl_write() toggles it
> - tracing_read_pipe() tests it
> - tracer_alloc_buffers() uses it
> And other tracers seem to use it a lot.
>
> Mmiotrace does use the tracer::ctrl_update hook, and allow/disallow
> calls to __trace_mmiotrace_{rw,map}() via enabling/disabling the whole
> mmiotrace core. Is this not enough, or is it inappropriate?
>
> It seems tracer_enabled is used by the trace framework itself to
> enable/disable... what? Hmm, maybe nothing I care about.
>
> Should mmiotrace simply do
>        tracer_enabled = 1;
> in mmio_trace_init()?
>
> Should mmiotrace test tracer_enabled, and if so, when?


As I said to you, I met the same bug of this early quit of the pipe.
But I should give here more details.
This bug occurs with -tip (a version pulled 2 days ago so trace.c
didn't change).
I never saw it with other tracers than mmiotrace. I had no problem
with sched_switch or function tracer.

It happened when I was writing the tracer marker. So I'm not sure if
the origin is here. If I'm not wrong it happened whithout adding mark
messages too.
Can you tell me if your pipe quits when you add a mark or if this bug
occurs on other cases too?

I will try to reproduce the bug this evening.

Re: Tracing/ftrace: trouble with trace_entries and trace_pipe

[Pekka Paalanen]

On Mon, 15 Sep 2008 17:14:34 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Mon, 15 Sep 2008, Pekka Paalanen wrote:
> 
> > Hi Steven and others,
> > 
> > first a minor bug: it seems the units of /debug/tracing/trace_entries
> > is different for read and write. This is confusing for the users, since
> > I can't say "if you have problems, double it". If I read from it
> > something like 16422, then write back 16422, next I read 214. I can't
> > recall the exact numbers, but the difference really is two orders of
> > magnitude. I have 1 GB RAM in this box, so that shouldn't be an issue.
> 
> You write to it the same number that you read from and it returned 
> something different?? That is indeed a bug, since it should definitely 
> detect that. Is this linux-tip? I'll have to play with it to make sure 
> nothing broke it recently.
> 
> I just tried the latest mainline, and it seemed to work there.

Yes, it returned a very different number. This is Ingo's tip/master,
sorry for not being explicit. Checked-out on Sunday.

Echoing the following numbers to trace_entries triggers it:
200, 64, 640, 16422, 16422, 16422, 164220...
so the ridiculously small number 64 does something bad. After 640,
I read back something less than 200. Each following write increases
that number by 46.
16422 is the default before writing anything.
That is even stranger than I thought. :-o

I was going to test the buffer overflow with mmiotrace.

> > My other problem is with trace_pipe. It is again making 'cat' quit too
> > early. The condition triggered is
> > 	if (!tracer_enabled && iter->pos) {
> > in tracing_read_pipe(), and it is followed by triggering
> >         /* stop when tracing is finished */
> >         if (trace_empty(iter)) {
> > and then sret=0, so read returns 0 and 'cat' exits.
> > 
> > Now, I am trying my mmiotrace marker patches, but as far as I can tell,
> > nothing I modified is the reason for this. I didn't yet explicitly test
> > for it, though. I'll send these patches after I hear from Frederic.
> > 
> > The cat-quit problem is not a constant state. After boot, I could play
> > with my markers and testmmiotrace without cat quitting. Then something
> > happens, and cat starts the quitting behaviour, and won't get to normal
> > by disabling and enabling mmiotrace.
> > 
> > I have a couple of wild guesses of what might be related:
> > - ring buffer wrap-around
> > - ring buffer overflow (at first try I hit these, the second try
> > after putting debug-pr_info's in place I don't hit this)
> > - ring buffer resize (after playing with trace_entries, cat-quit
> > problem was present, though it might have been present before)
> > 
> > After viewing the git history, I have some more guesses, mainly
> > related to setting tracer_enabled to 0.
> > - commit 2b1bce1787700768cbc87c8509851c6f49d252dc
> > I don't see where tracer_enabled would be set to 1, when
> > mmiotrace is enabled. It used to default to 1 and mmiotrace was happy.
> > - __tracing_open() sets it to 0 (not called for the pipe)
> > - tracing_release() sets it to 1
> > - tracing_ctrl_write() toggles it
> > - tracing_read_pipe() tests it
> > - tracer_alloc_buffers() uses it
> > And other tracers seem to use it a lot.
> > 
> > Mmiotrace does use the tracer::ctrl_update hook, and allow/disallow
> > calls to __trace_mmiotrace_{rw,map}() via enabling/disabling the whole
> > mmiotrace core. Is this not enough, or is it inappropriate?
> > 
> > It seems tracer_enabled is used by the trace framework itself to
> > enable/disable... what? Hmm, maybe nothing I care about.
> > 
> > Should mmiotrace simply do
> > 	tracer_enabled = 1;
> > in mmio_trace_init()?
> > 
> > Should mmiotrace test tracer_enabled, and if so, when?
> 
> No, tracer_enabled is something that is internal to the tracer 
> infrastructure. 
> 
> if you read from either tracing/trace or tracing/latency_trace it will 
> disable the tracer while you dump. But you should not be doing that. The 
> trace_pipe should not disable that either.

Ok, so the problem is probably the commit I mentioned. It makes the
no_tracer tracer to set tracer_enabled to 0, and I can't find where
it would be set to 1 for mmiotrace. And this interferes with
tracing_read_pipe(), making it quit when iter->pos is non-zero.
See no_trace_init() in trace.c. According to this, the cat-quit
occurs when the buffer gets empty after first data, but this isn't
totally in agreement with what I recall from my experiments. And it
does happen also on other times than injecting markers.

So either it is wrong to check tracer_enabled in tracing_read_pipe(),
or no_trace_init() should not touch it.

Steven, what do you think?

-- 
Pekka Paalanen
http://www.iki.fi/pq/

[PATCH 1/7] x86 mmiotrace: fix a rare memory leak.

[Pekka Paalanen]

>From da74191de5e5a3c0adee0604757d19b2faf8ec79 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sat, 23 Aug 2008 14:32:22 +0300
Subject: [PATCH] x86 mmiotrace: fix a rare memory leak.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 arch/x86/mm/mmio-mod.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 635b50e..754bd1e 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -307,8 +307,10 @@ static void ioremap_trace_core(resource_size_t offset, unsigned long size,
 	map.map_id = trace->id;
 
 	spin_lock_irq(&trace_lock);
-	if (!is_enabled())
+	if (!is_enabled()) {
+		kfree(trace);
 		goto not_enabled;
+	}
 
 	mmio_trace_mapping(&map);
 	list_add_tail(&trace->list, &trace_list);
-- 
1.5.6.4

[PATCH 2/7] ftrace: move mmiotrace functions out of trace.c.

[Pekka Paalanen]

>From 743cab2763d3e8d9f4d3b82a02fcdc5ad8a13c04 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 16:53:05 +0300
Subject: [PATCH] ftrace: move mmiotrace functions out of trace.c.

Moves the mmiotrace specific functions from trace.c to
trace_mmiotrace.c. Functions trace_wake_up(), tracing_get_trace_entry(),
and tracing_generic_entry_update() are therefore made available outside
trace.c.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace.c           |   46 +--------------------------------------
 kernel/trace/trace.h           |   15 +++++-------
 kernel/trace/trace_mmiotrace.c |   42 ++++++++++++++++++++++++++++++++++++
 3 files changed, 50 insertions(+), 53 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 7e6cb4f..d372bc5 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -785,7 +785,7 @@ trace_next_page(struct trace_array_cpu *data, void *addr)
 	return page_address(page);
 }
 
-static inline struct trace_entry *
+struct trace_entry *
 tracing_get_trace_entry(struct trace_array *tr, struct trace_array_cpu *data)
 {
 	unsigned long idx, idx_next;
@@ -821,7 +821,7 @@ tracing_get_trace_entry(struct trace_array *tr, struct trace_array_cpu *data)
 	return entry;
 }
 
-static inline void
+void
 tracing_generic_entry_update(struct trace_entry *entry, unsigned long flags)
 {
 	struct task_struct *tsk = current;
@@ -865,48 +865,6 @@ ftrace(struct trace_array *tr, struct trace_array_cpu *data,
 		trace_function(tr, data, ip, parent_ip, flags);
 }
 
-#ifdef CONFIG_MMIOTRACE
-void __trace_mmiotrace_rw(struct trace_array *tr, struct trace_array_cpu *data,
-						struct mmiotrace_rw *rw)
-{
-	struct trace_entry *entry;
-	unsigned long irq_flags;
-
-	raw_local_irq_save(irq_flags);
-	__raw_spin_lock(&data->lock);
-
-	entry				= tracing_get_trace_entry(tr, data);
-	tracing_generic_entry_update(entry, 0);
-	entry->type			= TRACE_MMIO_RW;
-	entry->field.mmiorw		= *rw;
-
-	__raw_spin_unlock(&data->lock);
-	raw_local_irq_restore(irq_flags);
-
-	trace_wake_up();
-}
-
-void __trace_mmiotrace_map(struct trace_array *tr, struct trace_array_cpu *data,
-						struct mmiotrace_map *map)
-{
-	struct trace_entry *entry;
-	unsigned long irq_flags;
-
-	raw_local_irq_save(irq_flags);
-	__raw_spin_lock(&data->lock);
-
-	entry				= tracing_get_trace_entry(tr, data);
-	tracing_generic_entry_update(entry, 0);
-	entry->type			= TRACE_MMIO_MAP;
-	entry->field.mmiomap		= *map;
-
-	__raw_spin_unlock(&data->lock);
-	raw_local_irq_restore(irq_flags);
-
-	trace_wake_up();
-}
-#endif
-
 void __trace_stack(struct trace_array *tr,
 		   struct trace_array_cpu *data,
 		   unsigned long flags,
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 77c265f..9d39aa0 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -213,11 +213,17 @@ struct trace_iterator {
 	long			idx;
 };
 
+void trace_wake_up(void);
 void tracing_reset(struct trace_array_cpu *data);
 int tracing_open_generic(struct inode *inode, struct file *filp);
 struct dentry *tracing_init_dentry(void);
 void init_tracer_sysprof_debugfs(struct dentry *d_tracer);
 
+struct trace_entry *tracing_get_trace_entry(struct trace_array *tr,
+						struct trace_array_cpu *data);
+void tracing_generic_entry_update(struct trace_entry *entry,
+						unsigned long flags);
+
 void ftrace(struct trace_array *tr,
 			    struct trace_array_cpu *data,
 			    unsigned long ip,
@@ -291,15 +297,6 @@ extern unsigned long ftrace_update_tot_cnt;
 extern int DYN_FTRACE_TEST_NAME(void);
 #endif
 
-#ifdef CONFIG_MMIOTRACE
-extern void __trace_mmiotrace_rw(struct trace_array *tr,
-				struct trace_array_cpu *data,
-				struct mmiotrace_rw *rw);
-extern void __trace_mmiotrace_map(struct trace_array *tr,
-				struct trace_array_cpu *data,
-				struct mmiotrace_map *map);
-#endif
-
 #ifdef CONFIG_FTRACE_STARTUP_TEST
 #ifdef CONFIG_FTRACE
 extern int trace_selftest_startup_function(struct tracer *trace,
diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 9b7a936..ef02747 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -276,6 +276,27 @@ __init static int init_mmio_trace(void)
 }
 device_initcall(init_mmio_trace);
 
+static void __trace_mmiotrace_rw(struct trace_array *tr,
+				struct trace_array_cpu *data,
+				struct mmiotrace_rw *rw)
+{
+	struct trace_entry *entry;
+	unsigned long irq_flags;
+
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&data->lock);
+
+	entry				= tracing_get_trace_entry(tr, data);
+	tracing_generic_entry_update(entry, 0);
+	entry->type			= TRACE_MMIO_RW;
+	entry->field.mmiorw		= *rw;
+
+	__raw_spin_unlock(&data->lock);
+	raw_local_irq_restore(irq_flags);
+
+	trace_wake_up();
+}
+
 void mmio_trace_rw(struct mmiotrace_rw *rw)
 {
 	struct trace_array *tr = mmio_trace_array;
@@ -283,6 +304,27 @@ void mmio_trace_rw(struct mmiotrace_rw *rw)
 	__trace_mmiotrace_rw(tr, data, rw);
 }
 
+static void __trace_mmiotrace_map(struct trace_array *tr,
+				struct trace_array_cpu *data,
+				struct mmiotrace_map *map)
+{
+	struct trace_entry *entry;
+	unsigned long irq_flags;
+
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&data->lock);
+
+	entry				= tracing_get_trace_entry(tr, data);
+	tracing_generic_entry_update(entry, 0);
+	entry->type			= TRACE_MMIO_MAP;
+	entry->field.mmiomap		= *map;
+
+	__raw_spin_unlock(&data->lock);
+	raw_local_irq_restore(irq_flags);
+
+	trace_wake_up();
+}
+
 void mmio_trace_mapping(struct mmiotrace_map *map)
 {
 	struct trace_array *tr = mmio_trace_array;
-- 
1.5.6.4

[PATCH 3/7] ftrace: add trace_vprintk()

[Pekka Paalanen]

>From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 17:27:05 +0300
Subject: [PATCH] ftrace: add trace_vprintk()

trace_vprintk() for easier implementation of tracer specific *_printk
functions. Add check check for no_tracer, and implement
__ftrace_printk() as a wrapper.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace.c |   24 ++++++++++++++++++------
 kernel/trace/trace.h |    1 +
 2 files changed, 19 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index d372bc5..406de9c 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3054,7 +3054,7 @@ static __init void tracer_init_debugfs(void)
 	(sizeof(struct trace_field) - offsetof(struct trace_field, print.buf))
 #define TRACE_CONT_BUF_SIZE sizeof(struct trace_field)
 
-int __ftrace_printk(unsigned long ip, const char *fmt, ...)
+int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
 {
 	static DEFINE_SPINLOCK(trace_buf_lock);
 	static char trace_buf[TRACE_BUF_SIZE];
@@ -3064,10 +3064,9 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 	struct trace_entry *entry;
 	unsigned long flags;
 	long disabled;
-	va_list ap;
 	int cpu, len = 0, write, written = 0;
 
-	if (!(trace_flags & TRACE_ITER_PRINTK) || !tr->ctrl || tracing_disabled)
+	if (current_trace == &no_tracer || !tr->ctrl || tracing_disabled)
 		return 0;
 
 	local_irq_save(flags);
@@ -3079,9 +3078,7 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 		goto out;
 
 	spin_lock(&trace_buf_lock);
-	va_start(ap, fmt);
-	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, ap);
-	va_end(ap);
+	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
 
 	len = min(len, TRACE_BUF_SIZE-1);
 	trace_buf[len] = 0;
@@ -3120,6 +3117,21 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 
 	return len;
 }
+EXPORT_SYMBOL_GPL(trace_vprintk);
+
+int __ftrace_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, fmt, ap);
+	va_end(ap);
+	return ret;
+}
 EXPORT_SYMBOL_GPL(__ftrace_printk);
 
 static int trace_panic_handler(struct notifier_block *this,
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 9d39aa0..be3b3cf 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -333,6 +333,7 @@ extern int trace_seq_printf(struct trace_seq *s, const char *fmt, ...);
 extern ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf,
 				 size_t cnt);
 extern long ns2usecs(cycle_t nsec);
+extern int trace_vprintk(unsigned long ip, const char *fmt, va_list args);
 
 extern unsigned long trace_flags;
 
-- 
1.5.6.4

[PATCH 4/7] x86 mmiotrace: implement mmiotrace_printk().

[Pekka Paalanen]

>From ca4db25e22b79fd77f4a7c6bb812e605379840a0 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 18:37:46 +0300
Subject: [PATCH] x86 mmiotrace: implement mmiotrace_printk().

Offer mmiotrace users a function to inject markers from inside the kernel.
This depends on the trace_vprintk() patch.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 arch/x86/mm/mmio-mod.c         |   19 ++++++++++++++++++-
 arch/x86/mm/testmmiotrace.c    |    4 ++++
 include/linux/mmiotrace.h      |   17 +++++++++++++++--
 kernel/trace/trace_mmiotrace.c |    5 +++++
 4 files changed, 42 insertions(+), 3 deletions(-)

diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 754bd1e..5e2e2e7 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -75,7 +75,7 @@ static LIST_HEAD(trace_list);		/* struct remap_trace */
  *   and trace_lock.
  * - Routines depending on is_enabled() must take trace_lock.
  * - trace_list users must hold trace_lock.
- * - is_enabled() guarantees that mmio_trace_record is allowed.
+ * - is_enabled() guarantees that mmio_trace_{rw,mapping} are allowed.
  * - pre/post callbacks assume the effect of is_enabled() being true.
  */
 
@@ -379,6 +379,23 @@ void mmiotrace_iounmap(volatile void __iomem *addr)
 		iounmap_trace_core(addr);
 }
 
+int mmiotrace_printk(const char *fmt, ...)
+{
+	int ret = 0;
+	va_list args;
+	unsigned long flags;
+	va_start(args, fmt);
+
+	spin_lock_irqsave(&trace_lock, flags);
+	if (is_enabled())
+		ret = mmio_trace_printk(fmt, args);
+	spin_unlock_irqrestore(&trace_lock, flags);
+
+	va_end(args);
+	return ret;
+}
+EXPORT_SYMBOL(mmiotrace_printk);
+
 static void clear_trace_list(void)
 {
 	struct remap_trace *trace;
diff --git a/arch/x86/mm/testmmiotrace.c b/arch/x86/mm/testmmiotrace.c
index d877c5b..ab50a8d 100644
--- a/arch/x86/mm/testmmiotrace.c
+++ b/arch/x86/mm/testmmiotrace.c
@@ -3,6 +3,7 @@
  */
 #include <linux/module.h>
 #include <linux/io.h>
+#include <linux/mmiotrace.h>
 
 #define MODULE_NAME "testmmiotrace"
 
@@ -13,6 +14,7 @@ MODULE_PARM_DESC(mmio_address, "Start address of the mapping of 16 kB.");
 static void do_write_test(void __iomem *p)
 {
 	unsigned int i;
+	mmiotrace_printk("Write test.\n");
 	for (i = 0; i < 256; i++)
 		iowrite8(i, p + i);
 	for (i = 1024; i < (5 * 1024); i += 2)
@@ -24,6 +26,7 @@ static void do_write_test(void __iomem *p)
 static void do_read_test(void __iomem *p)
 {
 	unsigned int i;
+	mmiotrace_printk("Read test.\n");
 	for (i = 0; i < 256; i++)
 		ioread8(p + i);
 	for (i = 1024; i < (5 * 1024); i += 2)
@@ -39,6 +42,7 @@ static void do_test(void)
 		pr_err(MODULE_NAME ": could not ioremap, aborting.\n");
 		return;
 	}
+	mmiotrace_printk("ioremap returned %p.\n", p);
 	do_write_test(p);
 	do_read_test(p);
 	iounmap(p);
diff --git a/include/linux/mmiotrace.h b/include/linux/mmiotrace.h
index 61d19e1..60cc3bf 100644
--- a/include/linux/mmiotrace.h
+++ b/include/linux/mmiotrace.h
@@ -34,11 +34,15 @@ extern void unregister_kmmio_probe(struct kmmio_probe *p);
 /* Called from page fault handler. */
 extern int kmmio_handler(struct pt_regs *regs, unsigned long addr);
 
-/* Called from ioremap.c */
 #ifdef CONFIG_MMIOTRACE
+/* Called from ioremap.c */
 extern void mmiotrace_ioremap(resource_size_t offset, unsigned long size,
 							void __iomem *addr);
 extern void mmiotrace_iounmap(volatile void __iomem *addr);
+
+/* For anyone to insert markers. Remember trailing newline. */
+extern int mmiotrace_printk(const char *fmt, ...)
+				__attribute__ ((format (printf, 1, 2)));
 #else
 static inline void mmiotrace_ioremap(resource_size_t offset,
 					unsigned long size, void __iomem *addr)
@@ -48,7 +52,15 @@ static inline void mmiotrace_ioremap(resource_size_t offset,
 static inline void mmiotrace_iounmap(volatile void __iomem *addr)
 {
 }
-#endif /* CONFIG_MMIOTRACE_HOOKS */
+
+static inline int mmiotrace_printk(const char *fmt, ...)
+				__attribute__ ((format (printf, 1, 0)));
+
+static inline int mmiotrace_printk(const char *fmt, ...)
+{
+	return 0;
+}
+#endif /* CONFIG_MMIOTRACE */
 
 enum mm_io_opcode {
 	MMIO_READ = 0x1,     /* struct mmiotrace_rw */
@@ -81,5 +93,6 @@ extern void enable_mmiotrace(void);
 extern void disable_mmiotrace(void);
 extern void mmio_trace_rw(struct mmiotrace_rw *rw);
 extern void mmio_trace_mapping(struct mmiotrace_map *map);
+extern int mmio_trace_printk(const char *fmt, va_list args);
 
 #endif /* MMIOTRACE_H */
diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index ef02747..767d1fa 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -335,3 +335,8 @@ void mmio_trace_mapping(struct mmiotrace_map *map)
 	__trace_mmiotrace_map(tr, data, map);
 	preempt_enable();
 }
+
+int mmio_trace_printk(const char *fmt, va_list args)
+{
+	return trace_vprintk(0, fmt, args);
+}
-- 
1.5.6.4

[PATCH 5/7] mmiotrace: handle TRACE_PRINT entries.

[Pekka Paalanen]

>From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 17 Aug 2008 18:15:13 +0300
Subject: [PATCH] mmiotrace: handle TRACE_PRINT entries.

Also make trace_seq_print_cont() non-static, and add a newline if the
seq buffer can't hold all data.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 kernel/trace/trace.c           |   31 +++++++++++--------------------
 kernel/trace/trace.h           |   19 +++++++++++++++++++
 kernel/trace/trace_mmiotrace.c |   23 +++++++++++++++++++++++
 3 files changed, 53 insertions(+), 20 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 406de9c..7e7154f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -200,23 +200,6 @@ unsigned long nsecs_to_usecs(unsigned long nsecs)
 }
 
 /*
- * trace_flag_type is an enumeration that holds different
- * states when a trace occurs. These are:
- *  IRQS_OFF	- interrupts were disabled
- *  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,
-};
-
-/*
  * TRACE_ITER_SYM_MASK masks the options in trace_flags that
  * control the output of kernel symbols.
  */
@@ -1517,12 +1500,16 @@ lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs,
 
 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)
+/*
+ * The message is supposed to contain an ending newline.
+ * If the printing stops prematurely, try to add a newline of our own.
+ */
+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;
+	bool ok = true;
 
 	ent = trace_entry_idx(tr, data, iter, iter->cpu);
 	if (!ent || ent->type != TRACE_CONT) {
@@ -1531,10 +1518,14 @@ trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
 	}
 
 	do {
-		trace_seq_printf(s, "%s", ent->cont.buf);
+		if (ok)
+			ok = (trace_seq_printf(s, "%s", ent->cont.buf) > 0);
 		__trace_iterator_increment(iter, iter->cpu);
 		ent = trace_entry_idx(tr, data, iter, iter->cpu);
 	} while (ent && ent->type == TRACE_CONT);
+
+	if (!ok)
+		trace_seq_putc(s, '\n');
 }
 
 static int
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index be3b3cf..648433d 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -72,6 +72,23 @@ struct print_entry {
 };
 
 /*
+ * trace_flag_type is an enumeration that holds different
+ * states when a trace occurs. These are:
+ *  IRQS_OFF	- interrupts were disabled
+ *  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,
+};
+
+/*
  * 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:
  *
@@ -330,6 +347,8 @@ extern int trace_selftest_startup_sysprof(struct tracer *trace,
 
 extern void *head_page(struct trace_array_cpu *data);
 extern int trace_seq_printf(struct trace_seq *s, const char *fmt, ...);
+extern void trace_seq_print_cont(struct trace_seq *s,
+				 struct trace_iterator *iter);
 extern ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf,
 				 size_t cnt);
 extern long ns2usecs(cycle_t nsec);
diff --git a/kernel/trace/trace_mmiotrace.c b/kernel/trace/trace_mmiotrace.c
index 767d1fa..a108c32 100644
--- a/kernel/trace/trace_mmiotrace.c
+++ b/kernel/trace/trace_mmiotrace.c
@@ -245,6 +245,27 @@ static int mmio_print_map(struct trace_iterator *iter)
 	return 0;
 }
 
+static int mmio_print_mark(struct trace_iterator *iter)
+{
+	struct trace_entry *entry = iter->ent;
+	const char *msg		= entry->field.print.buf;
+	struct trace_seq *s	= &iter->seq;
+	unsigned long long t	= ns2usecs(entry->field.t);
+	unsigned long usec_rem	= do_div(t, 1000000ULL);
+	unsigned secs		= (unsigned long)t;
+	int ret;
+
+	/* The trailing newline must be in the message. */
+	ret = trace_seq_printf(s, "MARK %lu.%06lu %s", secs, usec_rem, msg);
+	if (!ret)
+		return 0;
+
+	if (entry->field.flags & TRACE_FLAG_CONT)
+		trace_seq_print_cont(s, iter);
+
+	return 1;
+}
+
 /* return 0 to abort printing without consuming current entry in pipe mode */
 static int mmio_print_line(struct trace_iterator *iter)
 {
@@ -253,6 +274,8 @@ static int mmio_print_line(struct trace_iterator *iter)
 		return mmio_print_rw(iter);
 	case TRACE_MMIO_MAP:
 		return mmio_print_map(iter);
+	case TRACE_PRINT:
+		return mmio_print_mark(iter);
 	default:
 		return 1; /* ignore unknown entries */
 	}
-- 
1.5.6.4

[PATCH 6/7] mmiotrace: remove left-over marker cruft.

[Pekka Paalanen]

>From abd3cadc69143804cf4b0cf1d6fcadda5daad903 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 20:50:55 +0300
Subject: [PATCH] mmiotrace: remove left-over marker cruft.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 arch/x86/mm/mmio-mod.c    |   64 ---------------------------------------------
 include/linux/mmiotrace.h |    3 +-
 2 files changed, 1 insertions(+), 66 deletions(-)

diff --git a/arch/x86/mm/mmio-mod.c b/arch/x86/mm/mmio-mod.c
index 5e2e2e7..2c4baa8 100644
--- a/arch/x86/mm/mmio-mod.c
+++ b/arch/x86/mm/mmio-mod.c
@@ -56,13 +56,6 @@ struct remap_trace {
 static DEFINE_PER_CPU(struct trap_reason, pf_reason);
 static DEFINE_PER_CPU(struct mmiotrace_rw, cpu_trace);
 
-#if 0 /* XXX: no way gather this info anymore */
-/* Access to this is not per-cpu. */
-static DEFINE_PER_CPU(atomic_t, dropped);
-#endif
-
-static struct dentry *marker_file;
-
 static DEFINE_MUTEX(mmiotrace_mutex);
 static DEFINE_SPINLOCK(trace_lock);
 static atomic_t mmiotrace_enabled;
@@ -97,44 +90,6 @@ static bool is_enabled(void)
 	return atomic_read(&mmiotrace_enabled);
 }
 
-#if 0 /* XXX: needs rewrite */
-/*
- * Write callback for the debugfs entry:
- * Read a marker and write it to the mmio trace log
- */
-static ssize_t write_marker(struct file *file, const char __user *buffer,
-						size_t count, loff_t *ppos)
-{
-	char *event = NULL;
-	struct mm_io_header *headp;
-	ssize_t len = (count > 65535) ? 65535 : count;
-
-	event = kzalloc(sizeof(*headp) + len, GFP_KERNEL);
-	if (!event)
-		return -ENOMEM;
-
-	headp = (struct mm_io_header *)event;
-	headp->type = MMIO_MAGIC | (MMIO_MARKER << MMIO_OPCODE_SHIFT);
-	headp->data_len = len;
-
-	if (copy_from_user(event + sizeof(*headp), buffer, len)) {
-		kfree(event);
-		return -EFAULT;
-	}
-
-	spin_lock_irq(&trace_lock);
-#if 0 /* XXX: convert this to use tracing */
-	if (is_enabled())
-		relay_write(chan, event, sizeof(*headp) + len);
-	else
-#endif
-		len = -EINVAL;
-	spin_unlock_irq(&trace_lock);
-	kfree(event);
-	return len;
-}
-#endif
-
 static void print_pte(unsigned long address)
 {
 	unsigned int level;
@@ -481,26 +436,12 @@ static void leave_uniprocessor(void)
 }
 #endif
 
-#if 0 /* XXX: out of order */
-static struct file_operations fops_marker = {
-	.owner =	THIS_MODULE,
-	.write =	write_marker
-};
-#endif
-
 void enable_mmiotrace(void)
 {
 	mutex_lock(&mmiotrace_mutex);
 	if (is_enabled())
 		goto out;
 
-#if 0 /* XXX: tracing does not support text entries */
-	marker_file = debugfs_create_file("marker", 0660, dir, NULL,
-								&fops_marker);
-	if (!marker_file)
-		pr_err(NAME "marker file creation failed.\n");
-#endif
-
 	if (nommiotrace)
 		pr_info(NAME "MMIO tracing disabled.\n");
 	enter_uniprocessor();
@@ -525,11 +466,6 @@ void disable_mmiotrace(void)
 
 	clear_trace_list(); /* guarantees: no more kmmio callbacks */
 	leave_uniprocessor();
-	if (marker_file) {
-		debugfs_remove(marker_file);
-		marker_file = NULL;
-	}
-
 	pr_info(NAME "disabled.\n");
 out:
 	mutex_unlock(&mmiotrace_mutex);
diff --git a/include/linux/mmiotrace.h b/include/linux/mmiotrace.h
index 60cc3bf..139d7c8 100644
--- a/include/linux/mmiotrace.h
+++ b/include/linux/mmiotrace.h
@@ -67,8 +67,7 @@ enum mm_io_opcode {
 	MMIO_WRITE = 0x2,    /* struct mmiotrace_rw */
 	MMIO_PROBE = 0x3,    /* struct mmiotrace_map */
 	MMIO_UNPROBE = 0x4,  /* struct mmiotrace_map */
-	MMIO_MARKER = 0x5,   /* raw char data */
-	MMIO_UNKNOWN_OP = 0x6, /* struct mmiotrace_rw */
+	MMIO_UNKNOWN_OP = 0x5, /* struct mmiotrace_rw */
 };
 
 struct mmiotrace_rw {
-- 
1.5.6.4

[PATCH 7/7] ftrace: inject markers via trace_marker file.

[Pekka Paalanen]

>From 9be308e4ea3af69cebb29930757d6457f762866d Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <pq@iki.fi>
Date: Sun, 14 Sep 2008 22:34:35 +0300
Subject: [PATCH] ftrace: inject markers via trace_marker file.
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

Allow a user to inject a marker (TRACE_PRINT entry) into the trace ring
buffer. The related file operations are derived from code by Frédéric
Weisbecker <fweisbec@gmail.com>.

Signed-off-by: Pekka Paalanen <pq@iki.fi>
---
 Documentation/tracers/mmiotrace.txt |    5 +-
 kernel/trace/trace.c                |   76 ++++++++++++++++++++++++++++++++--
 kernel/trace/trace.h                |    4 ++
 3 files changed, 77 insertions(+), 8 deletions(-)

diff --git a/Documentation/tracers/mmiotrace.txt b/Documentation/tracers/mmiotrace.txt
index a4afb56..5bbbe20 100644
--- a/Documentation/tracers/mmiotrace.txt
+++ b/Documentation/tracers/mmiotrace.txt
@@ -36,7 +36,7 @@ $ mount -t debugfs debugfs /debug
 $ echo mmiotrace > /debug/tracing/current_tracer
 $ cat /debug/tracing/trace_pipe > mydump.txt &
 Start X or whatever.
-$ echo "X is up" > /debug/tracing/marker
+$ echo "X is up" > /debug/tracing/trace_marker
 $ echo none > /debug/tracing/current_tracer
 Check for lost events.
 
@@ -59,9 +59,8 @@ The 'cat' process should stay running (sleeping) in the background.
 Load the driver you want to trace and use it. Mmiotrace will only catch MMIO
 accesses to areas that are ioremapped while mmiotrace is active.
 
-[Unimplemented feature:]
 During tracing you can place comments (markers) into the trace by
-$ echo "X is up" > /debug/tracing/marker
+$ echo "X is up" > /debug/tracing/trace_marker
 This makes it easier to see which part of the (huge) trace corresponds to
 which action. It is recommended to place descriptive markers about what you
 do.
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 7e7154f..eee1fd9 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2879,6 +2879,66 @@ tracing_entries_write(struct file *filp, const char __user *ubuf,
 	return cnt;
 }
 
+static int tracing_open_mark(struct inode *inode, struct file *filp)
+{
+	int ret;
+
+	ret = tracing_open_generic(inode, filp);
+	if (ret)
+		return ret;
+
+	if (current_trace == &no_tracer)
+		return -ENODEV;
+
+	return 0;
+}
+
+static int mark_printk(const char *fmt, ...)
+{
+	int ret;
+	va_list args;
+	va_start(args, fmt);
+	ret = trace_vprintk(0, fmt, args);
+	va_end(args);
+	return ret;
+}
+
+static ssize_t
+tracing_mark_write(struct file *filp, const char __user *ubuf,
+					size_t cnt, loff_t *fpos)
+{
+	char *buf;
+	char *end;
+	struct trace_array *tr = &global_trace;
+
+	if (current_trace == &no_tracer || !tr->ctrl || tracing_disabled)
+		return -EINVAL;
+
+	if (cnt > TRACE_BUF_SIZE)
+		cnt = TRACE_BUF_SIZE;
+
+	buf = kmalloc(cnt + 1, GFP_KERNEL);
+	if (buf == NULL)
+		return -ENOMEM;
+
+	if (copy_from_user(buf, ubuf, cnt)) {
+		kfree(buf);
+		return -EFAULT;
+	}
+
+	/* Cut from the first nil or newline. */
+	buf[cnt] = '\0';
+	end = strchr(buf, '\n');
+	if (end)
+		*end = '\0';
+
+	cnt = mark_printk("%s\n", buf);
+	kfree(buf);
+	*fpos += cnt;
+
+	return cnt;
+}
+
 static struct file_operations tracing_max_lat_fops = {
 	.open		= tracing_open_generic,
 	.read		= tracing_max_lat_read,
@@ -2910,6 +2970,11 @@ static struct file_operations tracing_entries_fops = {
 	.write		= tracing_entries_write,
 };
 
+static struct file_operations tracing_mark_fops = {
+	.open		= tracing_open_mark,
+	.write		= tracing_mark_write,
+};
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 static ssize_t
@@ -3027,6 +3092,12 @@ static __init void tracer_init_debugfs(void)
 		pr_warning("Could not create debugfs "
 			   "'trace_entries' entry\n");
 
+	entry = debugfs_create_file("trace_marker", 0220, d_tracer,
+				    NULL, &tracing_mark_fops);
+	if (!entry)
+		pr_warning("Could not create debugfs "
+			   "'trace_marker' entry\n");
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 	entry = debugfs_create_file("dyn_ftrace_total_info", 0444, d_tracer,
 				    &ftrace_update_tot_cnt,
@@ -3040,11 +3111,6 @@ static __init void tracer_init_debugfs(void)
 #endif
 }
 
-#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)
-
 int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
 {
 	static DEFINE_SPINLOCK(trace_buf_lock);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 648433d..42f65d0 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -124,6 +124,10 @@ struct trace_entry {
 };
 
 #define TRACE_ENTRY_SIZE	sizeof(struct trace_entry)
+#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)
 
 /*
  * The CPU trace array - it consists of thousands of trace entries
-- 
1.5.6.4

Re: [PATCH 3/7] ftrace: add trace_vprintk()

[Steven Rostedt]

On Tue, 16 Sep 2008, Pekka Paalanen wrote:

> From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
> From: Pekka Paalanen <pq@iki.fi>
> Date: Sun, 14 Sep 2008 17:27:05 +0300
> Subject: [PATCH] ftrace: add trace_vprintk()
> 
> trace_vprintk() for easier implementation of tracer specific *_printk
> functions. Add check check for no_tracer, and implement
> __ftrace_printk() as a wrapper.
> 
> Signed-off-by: Pekka Paalanen <pq@iki.fi>

Nice!

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH 5/7] mmiotrace: handle TRACE_PRINT entries.

[Steven Rostedt]

On Tue, 16 Sep 2008, Pekka Paalanen wrote:

> From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
> From: Pekka Paalanen <pq@iki.fi>
> Date: Sun, 17 Aug 2008 18:15:13 +0300
> Subject: [PATCH] mmiotrace: handle TRACE_PRINT entries.
> 
> Also make trace_seq_print_cont() non-static, and add a newline if the
> seq buffer can't hold all data.
> 
> Signed-off-by: Pekka Paalanen <pq@iki.fi>
> ---
>  kernel/trace/trace.c           |   31 +++++++++++--------------------
>  kernel/trace/trace.h           |   19 +++++++++++++++++++
>  kernel/trace/trace_mmiotrace.c |   23 +++++++++++++++++++++++
>  3 files changed, 53 insertions(+), 20 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 406de9c..7e7154f 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -200,23 +200,6 @@ unsigned long nsecs_to_usecs(unsigned long nsecs)
>  }
>  
>  /*
> - * trace_flag_type is an enumeration that holds different
> - * states when a trace occurs. These are:
> - *  IRQS_OFF	- interrupts were disabled
> - *  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,
> -};
> -
> -/*
>   * TRACE_ITER_SYM_MASK masks the options in trace_flags that
>   * control the output of kernel symbols.
>   */
> @@ -1517,12 +1500,16 @@ lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs,
>  
>  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)
> +/*
> + * The message is supposed to contain an ending newline.
> + * If the printing stops prematurely, try to add a newline of our own.
> + */
> +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;
> +	bool ok = true;

hmm, since when did the kernel have type bool?

>  
>  	ent = trace_entry_idx(tr, data, iter, iter->cpu);
>  	if (!ent || ent->type != TRACE_CONT) {
> @@ -1531,10 +1518,14 @@ trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
>  	}
>  
>  	do {
> -		trace_seq_printf(s, "%s", ent->cont.buf);
> +		if (ok)
> +			ok = (trace_seq_printf(s, "%s", ent->cont.buf) > 0);
>  		__trace_iterator_increment(iter, iter->cpu);
>  		ent = trace_entry_idx(tr, data, iter, iter->cpu);
>  	} while (ent && ent->type == TRACE_CONT);
> +
> +	if (!ok)
> +		trace_seq_putc(s, '\n');
>  }
>  

-- Steve

Re: [PATCH 5/7] mmiotrace: handle TRACE_PRINT entries.

[Pekka Paalanen]

On Tue, 16 Sep 2008 16:11:20 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 16 Sep 2008, Pekka Paalanen wrote:
> 
> > From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
> > From: Pekka Paalanen <pq@iki.fi>
> > Date: Sun, 17 Aug 2008 18:15:13 +0300
> > Subject: [PATCH] mmiotrace: handle TRACE_PRINT entries.
> > 
> > Also make trace_seq_print_cont() non-static, and add a newline if the
> > seq buffer can't hold all data.
> > 
> > Signed-off-by: Pekka Paalanen <pq@iki.fi>
> > ---
> >  kernel/trace/trace.c           |   31 +++++++++++--------------------
> >  kernel/trace/trace.h           |   19 +++++++++++++++++++
> >  kernel/trace/trace_mmiotrace.c |   23 +++++++++++++++++++++++
> >  3 files changed, 53 insertions(+), 20 deletions(-)
> > 
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index 406de9c..7e7154f 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
...
> > @@ -1517,12 +1500,16 @@ lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs,
> >  
> >  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)
> > +/*
> > + * The message is supposed to contain an ending newline.
> > + * If the printing stops prematurely, try to add a newline of our own.
> > + */
> > +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;
> > +	bool ok = true;
> 
> hmm, since when did the kernel have type bool?

Good question. It seems to be used a lot. :-)

commit 6e21828743247270d09a86756a0c11702500dbfb
Author: Richard Knutsson <ricknu-0@student.ltu.se>
Date:   Sat Sep 30 23:27:11 2006 -0700

    [PATCH] Generic boolean
    
    This patch defines:
    * a generic boolean-type, named 'bool'
    * aliases to 0 and 1, named 'false' and 'true'
    
    Removing colliding definitions of 'bool', 'false' and 'true'.
    
    Signed-off-by: Richard Knutsson <ricknu-0@student.ltu.se>
    Signed-off-by: Andrew Morton <akpm@osdl.org>
    Signed-off-by: Linus Torvalds <torvalds@osdl.org>

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [PATCH 3/7] ftrace: add trace_vprintk()

[Ingo Molnar]

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

> 
> 
> On Tue, 16 Sep 2008, Pekka Paalanen wrote:
> 
> > From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
> > From: Pekka Paalanen <pq@iki.fi>
> > Date: Sun, 14 Sep 2008 17:27:05 +0300
> > Subject: [PATCH] ftrace: add trace_vprintk()
> > 
> > trace_vprintk() for easier implementation of tracer specific *_printk
> > functions. Add check check for no_tracer, and implement
> > __ftrace_printk() as a wrapper.
> > 
> > Signed-off-by: Pekka Paalanen <pq@iki.fi>
> 
> Nice!
> 
> Acked-by: Steven Rostedt <rostedt@goodmis.org>

nice - i've picked up Pekka's patches into tip/tracing/ftrace:

 f2e1ec3: ftrace: inject markers via trace_marker file
 574a7a7: mmiotrace: remove left-over marker cruft
 fb87810: mmiotrace: handle TRACE_PRINT entries
 eaa4f4e: x86 mmiotrace: implement mmiotrace_printk()
 d77a3b8: ftrace: add trace_vprintk()
 809fff6: ftrace: move mmiotrace functions out of trace.c
 bc94fff: x86 mmiotrace: fix a rare memory leak

and added your ack to all of them. Thanks,

	Ingo

Re: Tracing/ftrace: trouble with trace_entries and trace_pipe

[Frédéric Weisbecker]

2008/9/16 Pekka Paalanen <pq@iki.fi>:
> Ok, so the problem is probably the commit I mentioned. It makes the
> no_tracer tracer to set tracer_enabled to 0, and I can't find where
> it would be set to 1 for mmiotrace. And this interferes with
> tracing_read_pipe(), making it quit when iter->pos is non-zero.
> See no_trace_init() in trace.c. According to this, the cat-quit
> occurs when the buffer gets empty after first data, but this isn't
> totally in agreement with what I recall from my experiments. And it
> does happen also on other times than injecting markers.
>
> So either it is wrong to check tracer_enabled in tracing_read_pipe(),
> or no_trace_init() should not touch it.

Indeed that could be the problem.
None_tracer is chosen as the default tracer when the tracer engine
loads. But actually no_trace_init is not called at this time.

But if you set another tracer and reset current_tracer to none, you
will call no_trace_init. Since tracer_enabled is not reset to 1 with
other tracer's init functions, the problem occurs when you choose one
more time another tracer.

I think that mmiotrace receives a smaller flow of entries (depends on
the debugged module) whereas sched_switch or function's tracer, as an
example, are continuously fed and never enter the "while
(trace_empty(iter))" block. That's why I only see this bug in
mmiotrace.

Perhaps it would be a good idea to reenable tracer_enabled on
tracing_set_trace_write() just before calling the init callback of the
tracer chosen.

Re: Tracing/ftrace: trouble with trace_entries and trace_pipe

[Pekka Paalanen]

On Wed, 17 Sep 2008 14:41:29 +0200
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/9/16 Pekka Paalanen <pq@iki.fi>:
> > Ok, so the problem is probably the commit I mentioned. It makes the
> > no_tracer tracer to set tracer_enabled to 0, and I can't find where
> > it would be set to 1 for mmiotrace. And this interferes with
> > tracing_read_pipe(), making it quit when iter->pos is non-zero.
> > See no_trace_init() in trace.c. According to this, the cat-quit
> > occurs when the buffer gets empty after first data, but this isn't
> > totally in agreement with what I recall from my experiments. And it
> > does happen also on other times than injecting markers.
> >
> > So either it is wrong to check tracer_enabled in tracing_read_pipe(),
> > or no_trace_init() should not touch it.
> 
> Indeed that could be the problem.
> None_tracer is chosen as the default tracer when the tracer engine
> loads. But actually no_trace_init is not called at this time.
> 
> But if you set another tracer and reset current_tracer to none, you
> will call no_trace_init. Since tracer_enabled is not reset to 1 with
> other tracer's init functions, the problem occurs when you choose one
> more time another tracer.

Ah, this would explain the "non-deterministic" behaviour I saw.

> I think that mmiotrace receives a smaller flow of entries (depends on
> the debugged module) whereas sched_switch or function's tracer, as an
> example, are continuously fed and never enter the "while
> (trace_empty(iter))" block. That's why I only see this bug in
> mmiotrace.

Mmiotrace does see times, when there are a small number of events
coming, even when tracing a graphics driver. Sounds plausible.

> Perhaps it would be a good idea to reenable tracer_enabled on
> tracing_set_trace_write() just before calling the init callback of the
> tracer chosen.

That's a third option, yes.

Steven, what is the correct fix?

Frederic, thank you very much for testing this!

-- 
Pekka Paalanen
http://www.iki.fi/pq/