Re: [PATCH] ftrace: dump out ftrace buffers to console on panic

Andrew Morton
2008-07-30T21:31:19Z

On Wed, 30 Jul 2008 17:13:24 -0400 (EDT)
Steven Rostedt <rostedt@goodmis.org> wrote:

>
> 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 aweful long time
> otherwise.

The modern spelling is "awful" ;)

> Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> ---
> include/linux/ftrace.h | 6 +
> kernel/trace/Kconfig | 10 ++
> kernel/trace/trace.c | 179 ++++++++++++++++++++++++++++++++++++++++++++++++-
> 3 files changed, 194 insertions(+), 1 deletion(-)
>
> Index: linux-tip.git/kernel/trace/trace.c
> ===================================================================
> --- linux-tip.git.orig/kernel/trace/trace.c 2008-07-29 10:47:53.000000000 -0400
> +++ linux-tip.git/kernel/trace/trace.c 2008-07-30 16:46:15.000000000 -0400
> @@ -14,6 +14,7 @@
> #include <linux/utsrelease.h>
> #include <linux/kallsyms.h>
> #include <linux/seq_file.h>
> +#include <linux/notifier.h>

Your email client space-stuffed the patch.

> #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>
> @@ -104,7 +106,16 @@ int ftrace_function_enabled;
> * for a buffer. Note, the number of entries is always rounded
> * to ENTRIES_PER_PAGE.
> */
> -static unsigned long trace_nr_entries = 65536UL;
> +#ifdef CONFIG_FTRACE_DUMP_ON_OOPS
> +/*
> + * If dump on oops is defined, lower the number of entries.
> + * Usually this goes over the serial, and is used for debugging.

I suspect that (netconsole > serial) nowadays.

> + */
> +# define TRACE_ENTRIES_DEFAULT 16384UL
> +#else
> +# define TRACE_ENTRIES_DEFAULT 65536UL
> +#endif
> +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;
> @@ -2930,6 +2941,166 @@ static __init void tracer_init_debugfs(v
> #endif
> }
>
> +#ifdef CONFIG_FTRACE_DUMP_ON_OOPS
> +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
> +};
> +
> +static void
> +trace_printk_seq(struct trace_seq *s)
> +{
> + int len = s->len >= PAGE_SIZE ? PAGE_SIZE - 1 : s->len;

That's an open-coded min().

Beware that some architectures' PAGE_SIZE has unsigned long type and
others have a different type (unsigned?) so a min() on PAGE_SIZE will
warn on some architectures and not on others. min_t will fix that.

> + s->buffer[len] = 0;
>
> + printk("%s", s->buffer);

If the null-termination of ->buffer[] was actually needed then we have
a big problem here.

I'd suggest a conversion to vsnprintf().

> + trace_seq_reset(s);
> +}
> +
> +
> +static struct trace_iterator dump_iter;
> +static raw_spinlock_t ftrace_dump_lock =
> + (raw_spinlock_t)__RAW_SPIN_LOCK_UNLOCKED;

argh. Please never do an uncommented raw_spinlock_t. It's just
impossible for your readers to work out ytf it was chosen.

> +static int dump_running;
> +
> +void ftrace_dump(void)
> +{
> + struct trace_iterator *iter = &dump_iter;
> + struct trace_array_cpu *data;
> + static cpumask_t mask;
> + unsigned long flags;
> + int cpu, ret;
> + int cnt = 0;
> +
> + local_irq_save(flags);
> +
> + /* only one dump at a time */
> + __raw_spin_lock(&ftrace_dump_lock);

Should we have a __raw_spinlock_irqsave()?

> + if (dump_running)
> + ret = 1;
> + else {
> + dump_running = 1;
> + ret = 0;
> + }
> + __raw_spin_unlock(&ftrace_dump_lock);
> +
> + if (ret)
> + goto out;
> +
> + /* No turning back! */
> + ftrace_kill_atomic();
> +
> + printk("Dumping ftrace buffer:\n");

didst thou run checkpatch?

> + memset(iter, 0, sizeof(*iter));

This is zeroing out dump_iter, which is already zeroed. Is it needed?

> + iter->tr = &global_trace;
> + iter->trace = current_trace;

The use of local variable `iter' instead of simply using direct access
to dump_iter declarifies things. Perhaps it generates significantly
better code? If not, I'd suggest doing it the simple way.

dump_iter could be made local to this function.

> + /*
> + * 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("---------------------------------\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(" (ftrace buffer empty)\n");
> + else
> + printk("---------------------------------\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);
> + }

Can we combine those two loops into one?

> + __raw_spin_lock(&ftrace_dump_lock);
> + dump_running = 0;
> + __raw_spin_unlock(&ftrace_dump_lock);
> +
> + out:
> + local_irq_restore(flags);
> +}
> +#endif /* CONFIG_FTRACE_DUMP_ON_OOPS */

Do we really need a new config option for this? Would it hurt too much
to make it unconditionally available?