* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
[not found] <tip-4d4f88fa235f7f9ef8213564dc1804144332238b@git.kernel.org>
@ 2017-01-31 8:09 ` Dmitry Vyukov
2017-01-31 8:51 ` Ingo Molnar
0 siblings, 1 reply; 7+ messages in thread
From: Dmitry Vyukov @ 2017-01-31 8:09 UTC (permalink / raw)
To: Dmitry Vyukov, Ingo Molnar, H. Peter Anvin, Paul McKenney, LKML,
Thomas Gleixner
Cc: linux-tip-commits
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
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?).
> print_kernel_ident();
> - printk("-------------------------------\n");
> - printk("%s:%d %s!\n", file, line, s);
> - printk("\nother info that might help us debug this:\n\n");
> - printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> + pr_err("-------------------------------\n");
> + pr_err("%s:%d %s!\n", file, line, s);
> + pr_err("\nother info that might help us debug this:\n\n");
> + pr_err("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> !rcu_lockdep_current_cpu_online()
> ? "RCU used illegally from offline CPU!\n"
> : !rcu_is_watching()
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-01-31 8:09 ` [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err Dmitry Vyukov
@ 2017-01-31 8:51 ` Ingo Molnar
2017-01-31 9:11 ` Dmitry Vyukov
0 siblings, 1 reply; 7+ messages in thread
From: Ingo Molnar @ 2017-01-31 8:51 UTC (permalink / raw)
To: Dmitry Vyukov
Cc: H. Peter Anvin, Paul McKenney, LKML, Thomas Gleixner, linux-tip-commits
* 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,
Ingo
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-01-31 8:51 ` Ingo Molnar
@ 2017-01-31 9:11 ` Dmitry Vyukov
2017-01-31 9:17 ` Ingo Molnar
0 siblings, 1 reply; 7+ messages in thread
From: Dmitry Vyukov @ 2017-01-31 9:11 UTC (permalink / raw)
To: Ingo Molnar
Cc: H. Peter Anvin, Paul McKenney, LKML, Thomas Gleixner, linux-tip-commits
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.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-01-31 9:11 ` Dmitry Vyukov
@ 2017-01-31 9:17 ` Ingo Molnar
2017-01-31 15:49 ` Paul E. McKenney
0 siblings, 1 reply; 7+ messages in thread
From: Ingo Molnar @ 2017-01-31 9:17 UTC (permalink / raw)
To: Dmitry Vyukov
Cc: H. Peter Anvin, Paul McKenney, LKML, Thomas Gleixner, linux-tip-commits
* Dmitry Vyukov <dvyukov@google.com> 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.)
Thanks,
Ingo
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-01-31 9:17 ` Ingo Molnar
@ 2017-01-31 15:49 ` Paul E. McKenney
2017-02-01 11:07 ` Dmitry Vyukov
0 siblings, 1 reply; 7+ messages in thread
From: Paul E. McKenney @ 2017-01-31 15:49 UTC (permalink / raw)
To: Ingo Molnar
Cc: Dmitry Vyukov, H. Peter Anvin, LKML, Thomas Gleixner, linux-tip-commits
On Tue, Jan 31, 2017 at 10:17:57AM +0100, Ingo Molnar wrote:
>
> * Dmitry Vyukov <dvyukov@google.com> 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@linux.vnet.ibm.com>
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@google.com>
Reported-by: Ingo Molnar <mingo@kernel.org>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
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
@@ -1142,10 +1142,10 @@ print_circular_bug_header(struct lock_list *entry, unsigned int depth,
return 0;
printk("\n");
- printk("======================================================\n");
- printk("[ INFO: possible circular locking dependency detected ]\n");
+ pr_warn("======================================================\n");
+ pr_warn("WARNING: possible circular locking dependency detected\n");
print_kernel_ident();
- printk("-------------------------------------------------------\n");
+ pr_warn("------------------------------------------------------\n");
printk("%s/%d is trying to acquire lock:\n",
curr->comm, task_pid_nr(curr));
print_lock(check_src);
@@ -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",
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,
@@ -1709,10 +1709,10 @@ print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
return 0;
printk("\n");
- printk("=============================================\n");
- printk("[ INFO: possible recursive locking detected ]\n");
+ pr_warn("============================================\n");
+ pr_warn("WARNING: possible recursive locking detected\n");
print_kernel_ident();
- printk("---------------------------------------------\n");
+ pr_warn("--------------------------------------------\n");
printk("%s/%d is trying to acquire lock:\n",
curr->comm, task_pid_nr(curr));
print_lock(next);
@@ -2059,10 +2059,10 @@ static void print_collision(struct task_struct *curr,
struct lock_chain *chain)
{
printk("\n");
- printk("======================\n");
- printk("[chain_key collision ]\n");
+ pr_warn("============================\n");
+ pr_warn("WARNING: chain_key collision\n");
print_kernel_ident();
- printk("----------------------\n");
+ pr_warn("----------------------------\n");
printk("%s/%d: ", current->comm, task_pid_nr(current));
printk("Hash chain already cached but the contents don't match!\n");
@@ -2358,10 +2358,10 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this,
return 0;
printk("\n");
- printk("=================================\n");
- printk("[ INFO: inconsistent lock state ]\n");
+ pr_warn("================================\n");
+ pr_warn("WARNING: inconsistent lock state\n");
print_kernel_ident();
- printk("---------------------------------\n");
+ pr_warn("--------------------------------\n");
printk("inconsistent {%s} -> {%s} usage.\n",
usage_str[prev_bit], usage_str[new_bit]);
@@ -2423,10 +2423,10 @@ print_irq_inversion_bug(struct task_struct *curr,
return 0;
printk("\n");
- printk("=========================================================\n");
- printk("[ INFO: possible irq lock inversion dependency detected ]\n");
+ pr_warn("========================================================\n");
+ pr_warn("WARNING: possible irq lock inversion dependency detected\n");
print_kernel_ident();
- printk("---------------------------------------------------------\n");
+ pr_warn("--------------------------------------------------------\n");
printk("%s/%d just changed the state of lock:\n",
curr->comm, task_pid_nr(curr));
print_lock(this);
@@ -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");
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);
@@ -3374,10 +3374,10 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
return 0;
printk("\n");
- printk("=====================================\n");
- printk("[ BUG: bad unlock balance detected! ]\n");
+ pr_warn("=====================================\n");
+ pr_warn("WARNING: bad unlock balance detected!\n");
print_kernel_ident();
- printk("-------------------------------------\n");
+ pr_warn("-------------------------------------\n");
printk("%s/%d is trying to release lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
@@ -3871,10 +3871,10 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
return 0;
printk("\n");
- printk("=================================\n");
- printk("[ BUG: bad contention detected! ]\n");
+ pr_warn("=================================\n");
+ pr_warn("WARNING: bad contention detected!\n");
print_kernel_ident();
- printk("---------------------------------\n");
+ pr_warn("---------------------------------\n");
printk("%s/%d is trying to contend lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
@@ -4235,10 +4235,10 @@ print_freed_lock_bug(struct task_struct *curr, const void *mem_from,
return;
printk("\n");
- printk("=========================\n");
- printk("[ BUG: held lock freed! ]\n");
+ pr_warn("=========================\n");
+ pr_warn("WARNING: held lock freed!\n");
print_kernel_ident();
- printk("-------------------------\n");
+ pr_warn("-------------------------\n");
printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n",
curr->comm, task_pid_nr(curr), mem_from, mem_to-1);
print_lock(hlock);
@@ -4293,11 +4293,11 @@ static void print_held_locks_bug(void)
return;
printk("\n");
- printk("=====================================\n");
- printk("[ BUG: %s/%d still has locks held! ]\n",
+ pr_warn("====================================\n");
+ pr_warn("WARNING: %s/%d still has locks held!\n",
current->comm, task_pid_nr(current));
print_kernel_ident();
- printk("-------------------------------------\n");
+ pr_warn("------------------------------------\n");
lockdep_print_held_locks(current);
printk("\nstack backtrace:\n");
dump_stack();
@@ -4362,7 +4362,7 @@ void debug_show_all_locks(void)
} while_each_thread(g, p);
printk("\n");
- printk("=============================================\n\n");
+ pr_warn("=============================================\n\n");
if (unlock)
read_unlock(&tasklist_lock);
@@ -4392,10 +4392,10 @@ asmlinkage __visible void lockdep_sys_exit(void)
if (!debug_locks_off())
return;
printk("\n");
- printk("================================================\n");
- printk("[ BUG: lock held when returning to user space! ]\n");
+ pr_warn("================================================\n");
+ pr_warn("WARNING: lock held when returning to user space!\n");
print_kernel_ident();
- printk("------------------------------------------------\n");
+ pr_warn("------------------------------------------------\n");
printk("%s/%d is leaving the kernel with locks still held!\n",
curr->comm, curr->pid);
lockdep_print_held_locks(curr);
@@ -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");
- pr_err("===============================\n");
- pr_err("[ ERR: suspicious RCU usage. ]\n");
+ pr_warn("=============================\n");
+ pr_warn("WARNING: suspicious RCU usage\n");
print_kernel_ident();
- pr_err("-------------------------------\n");
- pr_err("%s:%d %s!\n", file, line, s);
- pr_err("\nother info that might help us debug this:\n\n");
- pr_err("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
+ pr_warn("-----------------------------\n");
+ printk("%s:%d %s!\n", file, line, s);
+ printk("\nother info that might help us debug this:\n\n");
+ printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
!rcu_lockdep_current_cpu_online()
? "RCU used illegally from offline CPU!\n"
: !rcu_is_watching()
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));
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-01-31 15:49 ` Paul E. McKenney
@ 2017-02-01 11:07 ` Dmitry Vyukov
2017-02-01 15:49 ` Paul E. McKenney
0 siblings, 1 reply; 7+ messages in thread
From: Dmitry Vyukov @ 2017-02-01 11:07 UTC (permalink / raw)
To: Paul McKenney
Cc: Ingo Molnar, H. Peter Anvin, LKML, Thomas Gleixner, linux-tip-commits
On Tue, Jan 31, 2017 at 4:49 PM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Tue, Jan 31, 2017 at 10:17:57AM +0100, Ingo Molnar wrote:
>>
>> * Dmitry Vyukov <dvyukov@google.com> 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@linux.vnet.ibm.com>
> 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@google.com>
> Reported-by: Ingo Molnar <mingo@kernel.org>
> Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>
> 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
> @@ -1142,10 +1142,10 @@ print_circular_bug_header(struct lock_list *entry, unsigned int depth,
> return 0;
>
> printk("\n");
> - printk("======================================================\n");
> - printk("[ INFO: possible circular locking dependency detected ]\n");
> + pr_warn("======================================================\n");
> + pr_warn("WARNING: possible circular locking dependency detected\n");
> print_kernel_ident();
> - printk("-------------------------------------------------------\n");
> + pr_warn("------------------------------------------------------\n");
> printk("%s/%d is trying to acquire lock:\n",
> curr->comm, task_pid_nr(curr));
> print_lock(check_src);
> @@ -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.
> 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,
> @@ -1709,10 +1709,10 @@ print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
> return 0;
>
> printk("\n");
> - printk("=============================================\n");
> - printk("[ INFO: possible recursive locking detected ]\n");
> + pr_warn("============================================\n");
> + pr_warn("WARNING: possible recursive locking detected\n");
> print_kernel_ident();
> - printk("---------------------------------------------\n");
> + pr_warn("--------------------------------------------\n");
> printk("%s/%d is trying to acquire lock:\n",
> curr->comm, task_pid_nr(curr));
> print_lock(next);
> @@ -2059,10 +2059,10 @@ static void print_collision(struct task_struct *curr,
> struct lock_chain *chain)
> {
> printk("\n");
> - printk("======================\n");
> - printk("[chain_key collision ]\n");
> + pr_warn("============================\n");
> + pr_warn("WARNING: chain_key collision\n");
> print_kernel_ident();
> - printk("----------------------\n");
> + pr_warn("----------------------------\n");
> printk("%s/%d: ", current->comm, task_pid_nr(current));
> printk("Hash chain already cached but the contents don't match!\n");
>
> @@ -2358,10 +2358,10 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this,
> return 0;
>
> printk("\n");
> - printk("=================================\n");
> - printk("[ INFO: inconsistent lock state ]\n");
> + pr_warn("================================\n");
> + pr_warn("WARNING: inconsistent lock state\n");
> print_kernel_ident();
> - printk("---------------------------------\n");
> + pr_warn("--------------------------------\n");
>
> printk("inconsistent {%s} -> {%s} usage.\n",
> usage_str[prev_bit], usage_str[new_bit]);
> @@ -2423,10 +2423,10 @@ print_irq_inversion_bug(struct task_struct *curr,
> return 0;
>
> printk("\n");
> - printk("=========================================================\n");
> - printk("[ INFO: possible irq lock inversion dependency detected ]\n");
> + pr_warn("========================================================\n");
> + pr_warn("WARNING: possible irq lock inversion dependency detected\n");
> print_kernel_ident();
> - printk("---------------------------------------------------------\n");
> + pr_warn("--------------------------------------------------------\n");
> printk("%s/%d just changed the state of lock:\n",
> curr->comm, task_pid_nr(curr));
> print_lock(this);
> @@ -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?
> 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);
> @@ -3374,10 +3374,10 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
> return 0;
>
> printk("\n");
> - printk("=====================================\n");
> - printk("[ BUG: bad unlock balance detected! ]\n");
> + pr_warn("=====================================\n");
> + pr_warn("WARNING: bad unlock balance detected!\n");
> print_kernel_ident();
> - printk("-------------------------------------\n");
> + pr_warn("-------------------------------------\n");
> printk("%s/%d is trying to release lock (",
> curr->comm, task_pid_nr(curr));
> print_lockdep_cache(lock);
> @@ -3871,10 +3871,10 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
> return 0;
>
> printk("\n");
> - printk("=================================\n");
> - printk("[ BUG: bad contention detected! ]\n");
> + pr_warn("=================================\n");
> + pr_warn("WARNING: bad contention detected!\n");
> print_kernel_ident();
> - printk("---------------------------------\n");
> + pr_warn("---------------------------------\n");
> printk("%s/%d is trying to contend lock (",
> curr->comm, task_pid_nr(curr));
> print_lockdep_cache(lock);
> @@ -4235,10 +4235,10 @@ print_freed_lock_bug(struct task_struct *curr, const void *mem_from,
> return;
>
> printk("\n");
> - printk("=========================\n");
> - printk("[ BUG: held lock freed! ]\n");
> + pr_warn("=========================\n");
> + pr_warn("WARNING: held lock freed!\n");
> print_kernel_ident();
> - printk("-------------------------\n");
> + pr_warn("-------------------------\n");
> printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n",
> curr->comm, task_pid_nr(curr), mem_from, mem_to-1);
> print_lock(hlock);
> @@ -4293,11 +4293,11 @@ static void print_held_locks_bug(void)
> return;
>
> printk("\n");
> - printk("=====================================\n");
> - printk("[ BUG: %s/%d still has locks held! ]\n",
> + pr_warn("====================================\n");
> + pr_warn("WARNING: %s/%d still has locks held!\n",
> current->comm, task_pid_nr(current));
> print_kernel_ident();
> - printk("-------------------------------------\n");
> + pr_warn("------------------------------------\n");
> lockdep_print_held_locks(current);
> printk("\nstack backtrace:\n");
> dump_stack();
> @@ -4362,7 +4362,7 @@ void debug_show_all_locks(void)
> } while_each_thread(g, p);
>
> printk("\n");
> - printk("=============================================\n\n");
> + pr_warn("=============================================\n\n");
>
> if (unlock)
> read_unlock(&tasklist_lock);
> @@ -4392,10 +4392,10 @@ asmlinkage __visible void lockdep_sys_exit(void)
> if (!debug_locks_off())
> return;
> printk("\n");
> - printk("================================================\n");
> - printk("[ BUG: lock held when returning to user space! ]\n");
> + pr_warn("================================================\n");
> + pr_warn("WARNING: lock held when returning to user space!\n");
> print_kernel_ident();
> - printk("------------------------------------------------\n");
> + pr_warn("------------------------------------------------\n");
> printk("%s/%d is leaving the kernel with locks still held!\n",
> curr->comm, curr->pid);
> lockdep_print_held_locks(curr);
> @@ -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");
> - pr_err("===============================\n");
> - pr_err("[ ERR: suspicious RCU usage. ]\n");
> + pr_warn("=============================\n");
> + pr_warn("WARNING: suspicious RCU usage\n");
> print_kernel_ident();
> - pr_err("-------------------------------\n");
> - pr_err("%s:%d %s!\n", file, line, s);
> - pr_err("\nother info that might help us debug this:\n\n");
> - pr_err("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> + pr_warn("-----------------------------\n");
> + printk("%s:%d %s!\n", file, line, s);
> + printk("\nother info that might help us debug this:\n\n");
> + printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n",
> !rcu_lockdep_current_cpu_online()
> ? "RCU used illegally from offline CPU!\n"
> : !rcu_is_watching()
> 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@google.com>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err
2017-02-01 11:07 ` Dmitry Vyukov
@ 2017-02-01 15:49 ` Paul E. McKenney
0 siblings, 0 replies; 7+ messages in thread
From: Paul E. McKenney @ 2017-02-01 15:49 UTC (permalink / raw)
To: Dmitry Vyukov
Cc: Ingo Molnar, H. Peter Anvin, LKML, Thomas Gleixner, linux-tip-commits
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@linux.vnet.ibm.com> wrote:
> > On Tue, Jan 31, 2017 at 10:17:57AM +0100, Ingo Molnar wrote:
> >>
> >> * Dmitry Vyukov <dvyukov@google.com> 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@linux.vnet.ibm.com>
> > 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@google.com>
> > Reported-by: Ingo Molnar <mingo@kernel.org>
> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >
> > 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@google.com>
Applied, thank you!
Thanx, Paul
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2017-02-01 15:49 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <tip-4d4f88fa235f7f9ef8213564dc1804144332238b@git.kernel.org>
2017-01-31 8:09 ` [tip:core/rcu] lockdep: Make RCU suspicious-access splats use pr_err Dmitry Vyukov
2017-01-31 8:51 ` Ingo Molnar
2017-01-31 9:11 ` Dmitry Vyukov
2017-01-31 9:17 ` Ingo Molnar
2017-01-31 15:49 ` Paul E. McKenney
2017-02-01 11:07 ` Dmitry Vyukov
2017-02-01 15:49 ` Paul E. McKenney
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.