Tracing/ftrace: Adds a marker to allow user comments

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.

Quoted 5 lines

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.

Quoted 1 line

It applies on last version of tip tree.

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

Ingo

2008/8/25 Ingo Molnar <[email protected]>:

Quoted 7 lines · Fr?d?ric Weisbecker

Quoted 5 lines

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.

Quoted 7 lines

Quoted 1 line

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

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 <[email protected]>

---
 kernel/trace/trace.c |  264 ++++++++++++++++++++++++++++++++++++--------------
 kernel/trace/trace.h |    5 +
 2 files changed, 198 insertions(+), 71 deletions(-)

kernel/trace/trace.c +193 -71

index 1801900..ee06849 100644
@@ -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)

kernel/trace/trace.h +1 -0

index 50b6d7a..ccc245c 100644
@@ -14,6 +14,7 @@ enum trace_type {
       TRACE_CTX,
       TRACE_WAKE,
       TRACE_CONT,
+       TRACE_MARK,
       TRACE_STACK,
       TRACE_PRINT,
       TRACE_SPECIAL,

2008/8/24 Frédéric Weisbecker <[email protected]>:

Quoted 79 lines

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 <[email protected]>

---
 kernel/trace/trace.c |  264 ++++++++++++++++++++++++++++++++++++--------------
 kernel/trace/trace.h |    5 +
 2 files changed, 198 insertions(+), 71 deletions(-)

kernel/trace/trace.c +59 -0

index 1801900..ee06849 100644
@@ -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;

kernel/trace/trace.c __trace_special(void *__tr, void *__data, · line 1024

Quoted 8 lines

kernel/trace/trace.c +8 -0

+
+       trace_print(buf, size, &tmp_ent, tr, data, flags);
+
+out:
+       atomic_dec(&data->disabled);
+       local_irq_restore(flags);
+       return size;
+}

Quoted 6 lines

kernel/trace/trace.c +6 -0

+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;

kernel/trace/trace.c __trace_special(void *__tr, void *__data, · line 1040

Quoted 8 lines

kernel/trace/trace.c +8 -0

+       struct trace_entry tmp_ent;
+       unsigned long flags;
+       long disabled;
+       va_list ap;
+       int cpu, len = 0;
+
+       if (likely(!ftrace_function_enabled))
+               return 0;

Quoted 64 lines

kernel/trace/trace.c +52 -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)
 

kernel/trace/trace.c static int trace_empty(struct trace_iterator *iter) · line 2101

Quoted 5 lines

kernel/trace/trace.c +3 -0

 static int print_trace_line(struct trace_iterator *iter)
 {
+       if (iter->ent->type == TRACE_MARK)
+               return print_mark(iter);
+

kernel/trace/trace.c static int trace_empty(struct trace_iterator *iter) · line 2103

Quoted 2 lines

kernel/trace/trace.c +0 -0

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

Quoted 153 lines

kernel/trace/trace.c +55 -71

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

kernel/trace/trace.h enum trace_type { · line 19

Quoted 13 lines

kernel/trace/trace.c +0 -0

 static int trace_panic_handler(struct notifier_block *this,
                              unsigned long event, void *unused)

kernel/trace/trace.h +1 -0

index 50b6d7a..ccc245c 100644
@@ -14,6 +14,7 @@ enum trace_type {
       TRACE_CTX,
       TRACE_WAKE,
       TRACE_CONT,
+       TRACE_MARK,
       TRACE_STACK,
       TRACE_PRINT,

Quoted 10 lines

kernel/trace/trace.h +4 -0

       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)
 

kernel/trace/trace.h struct trace_entry { · line 116

Quoted 3 lines

kernel/trace/trace.h +0 -0

 /*
 * 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)...

Quoted 3 lines

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.

Quoted 9 lines

Quoted 4 lines

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

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.

Quoted 6 lines

Quoted 6 lines

kernel/trace/trace.c +6 -0

+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;

Quoted 8 lines

kernel/trace/trace.c __trace_special(void *__tr, void *__data, · line 1040

Quoted 8 lines

kernel/trace/trace.c +8 -0

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

Quoted 5 lines

kernel/trace/trace.c static int trace_empty(struct trace_iterator *iter) · line 2101

Quoted 5 lines

static int print_trace_line(struct trace_iterator *iter) {

kernel/trace/trace.c +3 -0

+       if (iter->ent->type == TRACE_MARK)
+               return print_mark(iter);
+

Please, put this call after the following...

Quoted 2 lines

Quoted 2 lines

       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.

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.

2008/8/27 Pekka Paalanen <[email protected]>:

Quoted 6 lines

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.

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

Quoted 7 lines

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.

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.

Quoted 1 line · On Thu, 4 Sep 2008 18:20:09 +0200 "Fr?d?ric Weisbecker" <[email protected]>…

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.

Quoted 5 lines

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

2008/9/4 Steven Rostedt <[email protected]>:

Quoted 12 lines

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/)

Quoted 1 line

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

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?

Quoted 8 lines · 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.

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.

Quoted 47 lines

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

Quoted 1 line

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.

2008/9/16 Pekka Paalanen <[email protected]>:

Quoted 11 lines

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.

From da74191de5e5a3c0adee0604757d19b2faf8ec79 Mon Sep 17 00:00:00 2001

From 743cab2763d3e8d9f4d3b82a02fcdc5ad8a13c04 Mon Sep 17 00:00:00 2001

From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001

From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <[email protected]>
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 <[email protected]>

Quoted 9 lines · Pekka Paalanen

From 5579d3e6471201524697d1cc32fb37f1a4f70f95 Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <[email protected]>
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.

Quoted 1 line

Signed-off-by Pekka Paalanen <[email protected]>

Nice!

Acked-by Steven Rostedt <[email protected]>

From ca4db25e22b79fd77f4a7c6bb812e605379840a0 Mon Sep 17 00:00:00 2001

From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001

From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <[email protected]>
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 <[email protected]>

---
 kernel/trace/trace.c           |   31 +++++++++++--------------------
 kernel/trace/trace.h           |   19 +++++++++++++++++++
 kernel/trace/trace_mmiotrace.c |   23 +++++++++++++++++++++++
 3 files changed, 53 insertions(+), 20 deletions(-)

kernel/trace/trace.c +0 -19

index 406de9c..7e7154f 100644
@@ -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)

kernel/trace/trace.c +0 -1

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

Quoted 19 lines · Pekka Paalanen

From 6a458e250857907e16cb16799392fccbfd5f0f4a Mon Sep 17 00:00:00 2001
From: Pekka Paalanen <[email protected]>
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 <[email protected]>

---
 kernel/trace/trace.c           |   31 +++++++++++--------------------
 kernel/trace/trace.h           |   19 +++++++++++++++++++
 kernel/trace/trace_mmiotrace.c |   23 +++++++++++++++++++++++
 3 files changed, 53 insertions(+), 20 deletions(-)

kernel/trace/trace.c +0 -0

index 406de9c..7e7154f 100644

Quoted 4 lines

kernel/trace/trace.c +0 -0

@@ -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;
 

kernel/trace/trace.c lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs, · line 1512

Quoted 12 lines

kernel/trace/trace.c +6 -2

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

From abd3cadc69143804cf4b0cf1d6fcadda5daad903 Mon Sep 17 00:00:00 2001

From 9be308e4ea3af69cebb29930757d6457f762866d Mon Sep 17 00:00:00 2001

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?

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.

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?

Quoted 2 lines · Pekka Paalanen

Steven,

Quoted 2 lines

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.

Quoted 11 lines

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;

Quoted 8 lines

	}

	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.

Quoted 5 lines

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 '!').

Quoted 3 lines

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.

Quoted 2 lines

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.

Quoted 1 line

Steven, could you explain what is going on here?

Just did ;-)

Hope it helps,