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

[Paul E. McKenney]

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