Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err

From: Paul E. McKenney
Date: Wed Feb 01 2017 - 10:49:21 EST


On Wed, Feb 01, 2017 at 12:07:36PM +0100, Dmitry Vyukov wrote:
> On Tue, Jan 31, 2017 at 4:49 PM, Paul E. McKenney
> <paulmck@xxxxxxxxxxxxxxxxxx> wrote:
> > On Tue, Jan 31, 2017 at 10:17:57AM +0100, Ingo Molnar wrote:
> >>
> >> * Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
> >>
> >> > FWIW my vote is for:
> >> >
> >> > ==========================
> >> > WARNING: suspicious RCU usage
> >> > ==========================
> >>
> >> For heaven's sake make it:
> >>
> >> =============================
> >> WARNING: suspicious RCU usage
> >> =============================
> >>
> >> (Note the length of the start/stop lines.)
> >
> > Like this?
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > commit 45a2b28bb464a88ea886759c23a3cfa9b9b10055
> > Author: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> > Date: Tue Jan 31 07:45:13 2017 -0800
> >
> > lockdep: Use "WARNING" tag on lockdep splats
> >
> > This commit changes lockdep splats to begin lines with "WARNING" and
> > to use pr_warn() instead of printk(). This change eases scripted
> > analysis of kernel console output.
> >
> > Reported-by: Dmitry Vyukov <dvyukov@xxxxxxxxxx>
> > Reported-by: Ingo Molnar <mingo@xxxxxxxxxx>
> > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> >
> > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> > index d9a698e8458f..330648980789 100644
> > --- a/kernel/locking/lockdep.c
> > +++ b/kernel/locking/lockdep.c

[ . . . ]

> > @@ -1480,11 +1480,11 @@ print_bad_irq_dependency(struct task_struct *curr,
> > return 0;
> >
> > printk("\n");
> > - printk("======================================================\n");
> > - printk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n",
> > + pr_warn("=================================================\n");
> > + pr_warn("WARNING: %s-safe -> %s-unsafe lock order detected\n",
>
> The previous === line was 6 chars longer than the message (for %s expansion).
> Not sure if it matters much.

I am only seeing a 4-character difference, but good point. I restored the
extra characters here an on the line below.

> > irqclass, irqclass);
> > print_kernel_ident();
> > - printk("------------------------------------------------------\n");
> > + pr_warn("-------------------------------------------------\n");
> > printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n",
> > curr->comm, task_pid_nr(curr),
> > curr->hardirq_context, hardirq_count() >> HARDIRQ_SHIFT,

[ . . . ]

> > @@ -3168,10 +3168,10 @@ print_lock_nested_lock_not_held(struct task_struct *curr,
> > return 0;
> >
> > printk("\n");
> > - printk("==================================\n");
> > - printk("[ BUG: Nested lock was not taken ]\n");
> > + pr_warn("==================================\n");
> > + pr_warn("WARNING: Nested lock was not taken\n");
>
> Maybe s/Nested/nested/ of consistency?

I don't feel strongly either way. What do others think?

> > print_kernel_ident();
> > - printk("----------------------------------\n");
> > + pr_warn("----------------------------------\n");
> >
> > printk("%s/%d is trying to lock:\n", curr->comm, task_pid_nr(curr));
> > print_lock(hlock);

[ . . . ]

> > diff --git a/kernel/locking/rtmutex-debug.c b/kernel/locking/rtmutex-debug.c
> > index 62b6cee8ea7f..7f8a9e2ced6e 100644
> > --- a/kernel/locking/rtmutex-debug.c
> > +++ b/kernel/locking/rtmutex-debug.c
> > @@ -101,10 +101,11 @@ void debug_rt_mutex_print_deadlock(struct rt_mutex_waiter *waiter)
> > return;
> > }
> >
> > - printk("\n============================================\n");
> > - printk( "[ BUG: circular locking deadlock detected! ]\n");
> > - printk("%s\n", print_tainted());
> > - printk( "--------------------------------------------\n");
> > + pr_warn("\n");
> > + pr_warn("============================================\n");
> > + pr_warn("WARNING: circular locking deadlock detected!\n");
> > + pr_warn("%s\n", print_tainted());
> > + pr_warn("--------------------------------------------\n");
> > printk("%s/%d is deadlocking current task %s/%d\n\n",
> > task->comm, task_pid_nr(task),
> > current->comm, task_pid_nr(current));
>
> Acked-by: Dmitry Vyukov <dvyukov@xxxxxxxxxx>

Applied, thank you!

Thanx, Paul