]> git.proxmox.com Git - mirror_ubuntu-zesty-kernel.git/blobdiff - kernel/trace/trace.c
tracing/ftrace: tracing engine depends on Nop Tracer
[mirror_ubuntu-zesty-kernel.git] / kernel / trace / trace.c
index 97513c8ecd67274da2db006865f45a4dd0ffe090..eee1fd9648986e767bb21c9a89906f57d891f1ba 100644 (file)
@@ -199,23 +199,6 @@ unsigned long nsecs_to_usecs(unsigned long nsecs)
        return nsecs / 1000;
 }
 
-/*
- * 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.
@@ -235,6 +218,7 @@ static const char *trace_options[] = {
        "block",
        "stacktrace",
        "sched-tree",
+       "ftrace_printk",
        NULL
 };
 
@@ -784,7 +768,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;
@@ -820,7 +804,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;
@@ -864,48 +848,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,
@@ -976,6 +918,7 @@ tracing_sched_switch_trace(struct trace_array *tr,
        entry->field.ctx.next_pid       = next->pid;
        entry->field.ctx.next_prio      = next->prio;
        entry->field.ctx.next_state     = next->state;
+       entry->field.ctx.next_cpu       = task_cpu(next);
        __trace_stack(tr, data, flags, 5);
        __raw_spin_unlock(&data->lock);
        raw_local_irq_restore(irq_flags);
@@ -1002,6 +945,7 @@ tracing_sched_wakeup_trace(struct trace_array *tr,
        entry->field.ctx.next_pid       = wakee->pid;
        entry->field.ctx.next_prio      = wakee->prio;
        entry->field.ctx.next_state     = wakee->state;
+       entry->field.ctx.next_cpu       = task_cpu(wakee);
        __trace_stack(tr, data, flags, 6);
        __raw_spin_unlock(&data->lock);
        raw_local_irq_restore(irq_flags);
@@ -1117,9 +1061,8 @@ trace_entry_idx(struct trace_array *tr, struct trace_array_cpu *data,
 }
 
 /* Increment the index counter of an iterator by one */
-static void trace_iterator_increment(struct trace_iterator *iter, int cpu)
+static void __trace_iterator_increment(struct trace_iterator *iter, int cpu)
 {
-       iter->idx++;
        iter->next_idx[cpu]++;
        iter->next_page_idx[cpu]++;
 
@@ -1132,6 +1075,12 @@ static void trace_iterator_increment(struct trace_iterator *iter, int cpu)
        }
 }
 
+static void trace_iterator_increment(struct trace_iterator *iter, int cpu)
+{
+       iter->idx++;
+       __trace_iterator_increment(iter, cpu);
+}
+
 static struct trace_entry *
 trace_entry_next(struct trace_array *tr, struct trace_array_cpu *data,
                 struct trace_iterator *iter, int cpu)
@@ -1153,7 +1102,7 @@ trace_entry_next(struct trace_array *tr, struct trace_array_cpu *data,
 
        /* find a real entry */
        do {
-               trace_iterator_increment(iter, cpu);
+               __trace_iterator_increment(iter, cpu);
                ent = trace_entry_idx(tr, tr->data[cpu], iter, cpu);
        } while (ent && ent->type != TRACE_CONT);
 
@@ -1187,7 +1136,7 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu, int inc)
                                ent = trace_entry_next(tr, data, iter, cpu);
                        else {
                                while (ent && ent->type == TRACE_CONT) {
-                                       trace_iterator_increment(iter, cpu);
+                                       __trace_iterator_increment(iter, cpu);
                                        ent = trace_entry_idx(tr, tr->data[cpu],
                                                              iter, cpu);
                                }
@@ -1409,21 +1358,21 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)
 
 static void print_lat_help_header(struct seq_file *m)
 {
-       seq_puts(m, "#                _------=> CPU#            \n");
-       seq_puts(m, "#               / _-----=> irqs-off        \n");
-       seq_puts(m, "#              | / _----=> need-resched    \n");
-       seq_puts(m, "#              || / _---=> hardirq/softirq \n");
-       seq_puts(m, "#              ||| / _--=> preempt-depth   \n");
-       seq_puts(m, "#              |||| /                      \n");
-       seq_puts(m, "#              |||||     delay             \n");
-       seq_puts(m, "#  cmd     pid ||||| time  |   caller      \n");
-       seq_puts(m, "#     \\   /    |||||   \\   |   /           \n");
+       seq_puts(m, "#                  _------=> CPU#            \n");
+       seq_puts(m, "#                 / _-----=> irqs-off        \n");
+       seq_puts(m, "#                | / _----=> need-resched    \n");
+       seq_puts(m, "#                || / _---=> hardirq/softirq \n");
+       seq_puts(m, "#                ||| / _--=> preempt-depth   \n");
+       seq_puts(m, "#                |||| /                      \n");
+       seq_puts(m, "#                |||||     delay             \n");
+       seq_puts(m, "#  cmd     pid   ||||| time  |   caller      \n");
+       seq_puts(m, "#     \\   /      |||||   \\   |   /           \n");
 }
 
 static void print_func_help_header(struct seq_file *m)
 {
-       seq_puts(m, "#           TASK-PID   CPU#    TIMESTAMP  FUNCTION\n");
-       seq_puts(m, "#              | |      |          |         |\n");
+       seq_puts(m, "#           TASK-PID    CPU#    TIMESTAMP  FUNCTION\n");
+       seq_puts(m, "#              | |       |          |         |\n");
 }
 
 
@@ -1508,7 +1457,7 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
        comm = trace_find_cmdline(field->pid);
 
        trace_seq_printf(s, "%8.8s-%-5d ", comm, field->pid);
-       trace_seq_printf(s, "%d", cpu);
+       trace_seq_printf(s, "%3d", cpu);
        trace_seq_printf(s, "%c%c",
                        (field->flags & TRACE_FLAG_IRQS_OFF) ? 'd' : '.',
                        ((field->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
@@ -1551,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) {
@@ -1565,10 +1518,14 @@ trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
        }
 
        do {
-               trace_seq_printf(s, "%s", ent->cont.buf);
-               trace_iterator_increment(iter, iter->cpu);
+               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
@@ -1598,7 +1555,7 @@ print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
 
        if (verbose) {
                comm = trace_find_cmdline(field->pid);
-               trace_seq_printf(s, "%16s %5d %d %d %08x %08x [%08lx]"
+               trace_seq_printf(s, "%16s %5d %3d %d %08x %08x [%08lx]"
                                 " %ld.%03ldms (+%ld.%03ldms): ",
                                 comm,
                                 field->pid, cpu, field->flags,
@@ -1630,10 +1587,11 @@ print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
                        __ffs(field->ctx.prev_state) + 1 : 0;
                S = state < sizeof(state_to_char) - 1 ? state_to_char[state] : 'X';
                comm = trace_find_cmdline(field->ctx.next_pid);
-               trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c %s\n",
+               trace_seq_printf(s, " %5d:%3d:%c %s [%03d] %5d:%3d:%c %s\n",
                                 field->ctx.prev_pid,
                                 field->ctx.prev_prio,
                                 S, entry->type == TRACE_CTX ? "==>" : "  +",
+                                field->ctx.next_cpu,
                                 field->ctx.next_pid,
                                 field->ctx.next_prio,
                                 T, comm);
@@ -1655,7 +1613,7 @@ print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
        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)
+               if (field->flags & TRACE_FLAG_CONT)
                        trace_seq_print_cont(s, iter);
                break;
        default:
@@ -1694,7 +1652,7 @@ static int print_trace_fmt(struct trace_iterator *iter)
        ret = trace_seq_printf(s, "%16s-%-5d ", comm, field->pid);
        if (!ret)
                return 0;
-       ret = trace_seq_printf(s, "[%02d] ", iter->cpu);
+       ret = trace_seq_printf(s, "[%03d] ", iter->cpu);
        if (!ret)
                return 0;
        ret = trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem);
@@ -1730,11 +1688,12 @@ static int print_trace_fmt(struct trace_iterator *iter)
                        state_to_char[field->ctx.prev_state] : 'X';
                T = field->ctx.next_state < sizeof(state_to_char) ?
                        state_to_char[field->ctx.next_state] : 'X';
-               ret = trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c\n",
+               ret = trace_seq_printf(s, " %5d:%3d:%c %s [%03d] %5d:%3d:%c\n",
                                       field->ctx.prev_pid,
                                       field->ctx.prev_prio,
                                       S,
                                       entry->type == TRACE_CTX ? "==>" : "  +",
+                                      field->ctx.next_cpu,
                                       field->ctx.next_pid,
                                       field->ctx.next_prio,
                                       T);
@@ -1768,7 +1727,7 @@ static int print_trace_fmt(struct trace_iterator *iter)
        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)
+               if (field->flags & TRACE_FLAG_CONT)
                        trace_seq_print_cont(s, iter);
                break;
        }
@@ -1811,10 +1770,11 @@ static int print_raw_fmt(struct trace_iterator *iter)
                        state_to_char[field->ctx.next_state] : 'X';
                if (entry->type == TRACE_WAKE)
                        S = '+';
-               ret = trace_seq_printf(s, "%d %d %c %d %d %c\n",
+               ret = trace_seq_printf(s, "%d %d %c %d %d %d %c\n",
                                       field->ctx.prev_pid,
                                       field->ctx.prev_prio,
                                       S,
+                                      field->ctx.next_cpu,
                                       field->ctx.next_pid,
                                       field->ctx.next_prio,
                                       T);
@@ -1833,7 +1793,7 @@ static int print_raw_fmt(struct trace_iterator *iter)
        case TRACE_PRINT:
                trace_seq_printf(s, "# %lx %s",
                                 field->print.ip, field->print.buf);
-               if (field->flags && TRACE_FLAG_CONT)
+               if (field->flags & TRACE_FLAG_CONT)
                        trace_seq_print_cont(s, iter);
                break;
        }
@@ -1887,6 +1847,7 @@ static int print_hex_fmt(struct trace_iterator *iter)
                SEQ_PUT_HEX_FIELD_RET(s, field->ctx.prev_pid);
                SEQ_PUT_HEX_FIELD_RET(s, field->ctx.prev_prio);
                SEQ_PUT_HEX_FIELD_RET(s, S);
+               SEQ_PUT_HEX_FIELD_RET(s, field->ctx.next_cpu);
                SEQ_PUT_HEX_FIELD_RET(s, field->ctx.next_pid);
                SEQ_PUT_HEX_FIELD_RET(s, field->ctx.next_prio);
                SEQ_PUT_HEX_FIELD_RET(s, T);
@@ -2918,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,
@@ -2949,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
@@ -3030,12 +3056,12 @@ static __init void tracer_init_debugfs(void)
        entry = debugfs_create_file("available_tracers", 0444, d_tracer,
                                    &global_trace, &show_traces_fops);
        if (!entry)
-               pr_warning("Could not create debugfs 'trace' entry\n");
+               pr_warning("Could not create debugfs 'available_tracers' entry\n");
 
        entry = debugfs_create_file("current_tracer", 0444, d_tracer,
                                    &global_trace, &set_tracer_fops);
        if (!entry)
-               pr_warning("Could not create debugfs 'trace' entry\n");
+               pr_warning("Could not create debugfs 'current_tracer' entry\n");
 
        entry = debugfs_create_file("tracing_max_latency", 0644, d_tracer,
                                    &tracing_max_latency,
@@ -3048,7 +3074,7 @@ static __init void tracer_init_debugfs(void)
                                    &tracing_thresh, &tracing_max_lat_fops);
        if (!entry)
                pr_warning("Could not create debugfs "
-                          "'tracing_threash' entry\n");
+                          "'tracing_thresh' entry\n");
        entry = debugfs_create_file("README", 0644, d_tracer,
                                    NULL, &tracing_readme_fops);
        if (!entry)
@@ -3058,13 +3084,19 @@ static __init void tracer_init_debugfs(void)
                                    NULL, &tracing_pipe_fops);
        if (!entry)
                pr_warning("Could not create debugfs "
-                          "'tracing_threash' entry\n");
+                          "'trace_pipe' entry\n");
 
        entry = debugfs_create_file("trace_entries", 0644, d_tracer,
                                    &global_trace, &tracing_entries_fops);
        if (!entry)
                pr_warning("Could not create debugfs "
-                          "'tracing_threash' entry\n");
+                          "'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,
@@ -3079,24 +3111,19 @@ 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, ...)
+int trace_vprintk(unsigned long ip, const char *fmt, va_list args)
 {
-       struct trace_array *tr = &global_trace;
        static DEFINE_SPINLOCK(trace_buf_lock);
        static char trace_buf[TRACE_BUF_SIZE];
+
+       struct trace_array *tr = &global_trace;
        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))
+       if (current_trace == &no_tracer || !tr->ctrl || tracing_disabled)
                return 0;
 
        local_irq_save(flags);
@@ -3104,13 +3131,11 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
        data = tr->data[cpu];
        disabled = atomic_inc_return(&data->disabled);
 
-       if (unlikely(disabled != 1 || !ftrace_function_enabled))
+       if (unlikely(disabled != 1))
                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;
@@ -3149,6 +3174,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,