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

Steven Rostedt
2008-07-31T00:40:01Z

On Wed, 30 Jul 2008, Andrew Morton wrote:

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

I need to get spell check working with alpine :-/

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

Again, I just switched from pine to alpine, and ^R is not pulling in
patches correctly. I thought I fixed it, but I guess I did not :-(

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

Hmm, I find that serial is more reliable for me. Also it is what I usually
have when I debug a machine remotely.

>
>> + */
>> +# 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.

Thanks. This is cut and paste from another part of the code. I'll fix that
too.

>
>> + s->buffer[len] = 0;
>>
>> + printk("%s", s->buffer);
>
> If the null-termination of ->buffer[] was actually needed then we have
> a big problem here.

hehe, yeah, my first run filled up the page before printing, and I saw the
result of that. I changed the code later to print at each iteration,
which is much less than a page size. It should pretty much fit on a line.
Since the dump is the only user, I could just print the buffer without the
checks. I can put a warn on if the len is greater than some max, and
return.

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

OK. I'll add the comment. The reason for doing this is because it is a
special case in oops and not for normal use. If an oops happened in the
lockdep code, I don't want it to recursive fault here.

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

I'd like one but one doesn't exist. Actually, it is good we don't have one
because __raw_spin_lock should rarely be used.

Hmm, I think I should just change the whole thing back to normal
spin_locks and just hope that lockdep never oops ;-)

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

Damn, I thought I did, but obviously I didn't!

>
>> + memset(iter, 0, sizeof(*iter));
>
> This is zeroing out dump_iter, which is already zeroed. Is it needed?

Good point. No it isn't needed. I'll replace that with a comment.

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

I can make it local to this function. The reason for using iter, is that I
cut and pasted other code and modified it from there.

>
>> + /*
>> + * 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?

Yes but I kept it this way to match the semantics of the taking and
incrementing of the disabled atomic variable. The disabling is done first
but with a check to see if the buffers even exist, and we update mask to
match. Then we run the loop on the match and take the locks.

I feel safer on keeping the grabing of spinlocks and disabling the
buffers separate, as well as releasing them.

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

I don't mind making it unconditionally available. I only added the config
option because I thought people would like to turn it off.

I'll resubmit with the above concerns fixed and without the config option.

Thanks Andrew, as always, you give constructive feedback.

-- Steve