ftrace: dump out ftrace buffers to console on panic

At OLS I had a lot of interest to be able to have the ftrace buffers
dumped on panic.  Usually one would expect to uses kexec and examine
the buffers after a new kernel is loaded. But sometimes the resources
do not permit kdump and kexec, so having an option to still see the
sequence of events up to the crash is very advantageous.

This patch adds the option to have the ftrace buffers dumped to the
console in the latency_trace format on a panic. When the option is set,
the default entries per CPU buffer are lowered to 16384, since the writing
to the serial (if that is the console) may take an awful long time
otherwise.

[
 Changes since -v1:
  Got alpine to send correctly (as well as spell check working).
  Removed config option.
  Moved the static variables into ftrace_dump itself.
  Gave printk a log level.
]

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 018af16bce5c91ad1204f655ca953fdaddf11fc0..f7fb92045bf029992562080a8fd2038781818acc 100644 (file)
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -178,6 +178,7 @@ ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3);
 extern int
 __ftrace_printk(unsigned long ip, const char *fmt, ...)
        __attribute__ ((format (printf, 2, 3)));
+extern void ftrace_dump(void);
 #else
 static inline void
 ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3) { }
@@ -186,6 +187,7 @@ ftrace_printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 0)))
 {
        return 0;
 }
+static inline void ftrace_dump(void) { }
 #endif
 
 #ifdef CONFIG_FTRACE_MCOUNT_RECORD

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2597e7e49c35146d882f7271ba02fb116599ab72..97513c8ecd67274da2db006865f45a4dd0ffe090 100644 (file)
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -14,6 +14,7 @@
 #include <linux/utsrelease.h>
 #include <linux/kallsyms.h>
 #include <linux/seq_file.h>
+#include <linux/notifier.h>
 #include <linux/debugfs.h>
 #include <linux/pagemap.h>
 #include <linux/hardirq.h>
@@ -22,6 +23,7 @@
 #include <linux/ftrace.h>
 #include <linux/module.h>
 #include <linux/percpu.h>
+#include <linux/kdebug.h>
 #include <linux/ctype.h>
 #include <linux/init.h>
 #include <linux/poll.h>
@@ -103,8 +105,15 @@ int                                ftrace_function_enabled;
  * trace_nr_entries is the number of entries that is allocated
  * for a buffer. Note, the number of entries is always rounded
  * to ENTRIES_PER_PAGE.
+ *
+ * This number is purposely set to a low number of 16384.
+ * If the dump on oops happens, it will be much appreciated
+ * to not have to wait for all that output. Anyway this can be
+ * boot time and run time configurable.
  */
-static unsigned long           trace_nr_entries = 65536UL;
+#define TRACE_ENTRIES_DEFAULT  16384UL
+
+static unsigned long           trace_nr_entries = TRACE_ENTRIES_DEFAULT;
 
 /* trace_types holds a link list of available tracers. */
 static struct tracer           *trace_types __read_mostly;
@@ -3142,6 +3151,165 @@ int __ftrace_printk(unsigned long ip, const char *fmt, ...)
 }
 EXPORT_SYMBOL_GPL(__ftrace_printk);
 
+static int trace_panic_handler(struct notifier_block *this,
+                              unsigned long event, void *unused)
+{
+       ftrace_dump();
+       return NOTIFY_OK;
+}
+
+static struct notifier_block trace_panic_notifier = {
+       .notifier_call  = trace_panic_handler,
+       .next           = NULL,
+       .priority       = 150   /* priority: INT_MAX >= x >= 0 */
+};
+
+static int trace_die_handler(struct notifier_block *self,
+                            unsigned long val,
+                            void *data)
+{
+       switch (val) {
+       case DIE_OOPS:
+               ftrace_dump();
+               break;
+       default:
+               break;
+       }
+       return NOTIFY_OK;
+}
+
+static struct notifier_block trace_die_notifier = {
+       .notifier_call = trace_die_handler,
+       .priority = 200
+};
+
+/*
+ * printk is set to max of 1024, we really don't need it that big.
+ * Nothing should be printing 1000 characters anyway.
+ */
+#define TRACE_MAX_PRINT                1000
+
+/*
+ * Define here KERN_TRACE so that we have one place to modify
+ * it if we decide to change what log level the ftrace dump
+ * should be at.
+ */
+#define KERN_TRACE             KERN_INFO
+
+static void
+trace_printk_seq(struct trace_seq *s)
+{
+       /* Probably should print a warning here. */
+       if (s->len >= 1000)
+               s->len = 1000;
+
+       /* should be zero ended, but we are paranoid. */
+       s->buffer[s->len] = 0;
+
+       printk(KERN_TRACE "%s", s->buffer);
+
+       trace_seq_reset(s);
+}
+
+
+void ftrace_dump(void)
+{
+       static DEFINE_SPINLOCK(ftrace_dump_lock);
+       /* use static because iter can be a bit big for the stack */
+       static struct trace_iterator iter;
+       struct trace_array_cpu *data;
+       static cpumask_t mask;
+       static int dump_ran;
+       unsigned long flags;
+       int cnt = 0;
+       int cpu;
+
+       /* only one dump */
+       spin_lock_irqsave(&ftrace_dump_lock, flags);
+       if (dump_ran)
+               goto out;
+
+       dump_ran = 1;
+
+       /* No turning back! */
+       ftrace_kill_atomic();
+
+       printk(KERN_TRACE "Dumping ftrace buffer:\n");
+
+       iter.tr = &global_trace;
+       iter.trace = current_trace;
+
+       /*
+        * We need to stop all tracing on all CPUS to read the
+        * the next buffer. This is a bit expensive, but is
+        * not done often. We fill all what we can read,
+        * and then release the locks again.
+        */
+
+       cpus_clear(mask);
+
+       for_each_tracing_cpu(cpu) {
+               data = iter.tr->data[cpu];
+
+               if (!head_page(data) || !data->trace_idx)
+                       continue;
+
+               atomic_inc(&data->disabled);
+               cpu_set(cpu, mask);
+       }
+
+       for_each_cpu_mask(cpu, mask) {
+               data = iter.tr->data[cpu];
+               __raw_spin_lock(&data->lock);
+
+               if (data->overrun > iter.last_overrun[cpu])
+                       iter.overrun[cpu] +=
+                               data->overrun - iter.last_overrun[cpu];
+               iter.last_overrun[cpu] = data->overrun;
+       }
+
+       while (!trace_empty(&iter)) {
+
+               if (!cnt)
+                       printk(KERN_TRACE "---------------------------------\n");
+
+               cnt++;
+
+               /* reset all but tr, trace, and overruns */
+               memset(&iter.seq, 0,
+                      sizeof(struct trace_iterator) -
+                      offsetof(struct trace_iterator, seq));
+               iter.iter_flags |= TRACE_FILE_LAT_FMT;
+               iter.pos = -1;
+
+               if (find_next_entry_inc(&iter) != NULL) {
+                       print_trace_line(&iter);
+                       trace_consume(&iter);
+               }
+
+               trace_printk_seq(&iter.seq);
+       }
+
+       if (!cnt)
+               printk(KERN_TRACE "   (ftrace buffer empty)\n");
+       else
+               printk(KERN_TRACE "---------------------------------\n");
+
+       for_each_cpu_mask(cpu, mask) {
+               data = iter.tr->data[cpu];
+               __raw_spin_unlock(&data->lock);
+       }
+
+       for_each_cpu_mask(cpu, mask) {
+               data = iter.tr->data[cpu];
+               atomic_dec(&data->disabled);
+       }
+
+
+ out:
+       spin_unlock_irqrestore(&ftrace_dump_lock, flags);
+}
+
 static int trace_alloc_page(void)
 {
        struct trace_array_cpu *data;
@@ -3338,6 +3506,11 @@ __init static int tracer_alloc_buffers(void)
        global_trace.ctrl = tracer_enabled;
        tracing_disabled = 0;
 
+       atomic_notifier_chain_register(&panic_notifier_list,
+                                      &trace_panic_notifier);
+
+       register_die_notifier(&trace_die_notifier);
+
        return 0;
 
  free_buffers: