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

[Dmitry Vyukov <dvyukov@google.com>]

On Tue, Jan 31, 2017 at 9:51 AM, Ingo Molnar <mingo@kernel.org> wrote:
>
> * Dmitry Vyukov <dvyukov@google.com> wrote:
>
>> On Tue, Jan 31, 2017 at 8:54 AM, tip-bot for Paul E. McKenney
>> <tipbot@zytor.com> wrote:
>> > Commit-ID:  4d4f88fa235f7f9ef8213564dc1804144332238b
>> > Gitweb:     http://git.kernel.org/tip/4d4f88fa235f7f9ef8213564dc1804144332238b
>> > Author:     Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> > AuthorDate: Sat, 5 Nov 2016 04:17:15 -0700
>> > Committer:  Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> > CommitDate: Mon, 23 Jan 2017 11:31:54 -0800
>> >
>> > lockdep: Make RCU suspicious-access splats use pr_err
>> >
>> > This commit switches RCU suspicious-access splats use pr_err()
>> > instead of the current INFO printk()s.  This change makes it easier
>> > to automatically classify splats.
>> >
>> > Reported-by: Dmitry Vyukov <dvyukov@google.com>
>> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> > ---
>> >  kernel/locking/lockdep.c | 12 ++++++------
>> >  1 file changed, 6 insertions(+), 6 deletions(-)
>> >
>> > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
>> > index 7c38f8f..d9a698e 100644
>> > --- a/kernel/locking/lockdep.c
>> > +++ b/kernel/locking/lockdep.c
>> > @@ -4412,13 +4412,13 @@ void lockdep_rcu_suspicious(const char *file, const int line, const char *s)
>> >  #endif /* #ifdef CONFIG_PROVE_RCU_REPEATEDLY */
>> >         /* Note: the following can be executed concurrently, so be careful. */
>> >         printk("\n");
>> > -       printk("===============================\n");
>> > -       printk("[ INFO: suspicious RCU usage. ]\n");
>> > +       pr_err("===============================\n");
>> > +       pr_err("[ ERR: suspicious RCU usage.  ]\n");
>>
>>
>> Can we please make rcu reports look like all other kernel reports, e.g.:
>>
>> WARNING: suspicious RCU usage
>
> It was a prettification/typographical concept, as this:
>
>   ===============================
>   [ INFO: suspicious RCU usage. ]
>   ===============================
>
> looks better than this:
>
>   ===========================
>   INFO: suspicious RCU usage.
>   ===========================
>
>> I.e. prefix with a standard prefix (BUG/WARNING) and remove the [ ]
>> that are used only in rcu/lockdep reports (is there any particular
>> idea behind using [ ] in these reports and nowhere else?).
>
> So lockdep was the first subsystem who started using the INFO/WARNING style of
> coherent warning messages, and it spread elsewhere from there I think, minus
> typographical details.
>
> Arguably this would look even nicer:
>
>   ==============================
>   | INFO: suspicious RCU usage |
>   ==============================
>
> But I don't have very strong feelings about this and could live with this as well:
>
>   ==========================
>   INFO: suspicious RCU usage
>   ==========================
>
> (note the lack of the full stop.)


Thanks for the explanation. I concentrated on the grep-able bug line
itself, and frankly did not notice the row of ==== below. [ ] makes
sense now.

FWIW my vote is for:

==========================
WARNING: suspicious RCU usage
==========================

For background: we are working on automation of kernel testing and in
that context ideally all bug messages should allow to:
1. Easily understand that there is a bug (e.g. all start with
BUG:/WARNING:). INFO: is nasty, because there are some cases where it
is in fact only info, not something kernel developers should be
notified of. And just semantically, incorrect usage of synchronization
primitives and potential deadlocks does not qualify as just "info".
2. Easily understand boundaries (begin/end) of the bug message.
3. Extract some unique ID of the bug (e.g. "BUG: bug type in
function") for the purpose of deduplication.
4. Extract guilty file name for the purpose of finding owners/people to notify.

I am not saying that we need to do all this in this patch, just for information.