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

["Frédéric Weisbecker" <fweisbec@gmail.com>]

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