Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S966305AbdDSQ0W (ORCPT ); Wed, 19 Apr 2017 12:26:22 -0400 Received: from mx0b-001b2d01.pphosted.com ([148.163.158.5]:45861 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1762730AbdDSQ0S (ORCPT ); Wed, 19 Apr 2017 12:26:18 -0400 Date: Wed, 19 Apr 2017 09:26:10 -0700 From: "Paul E. McKenney" To: Josh Triplett Cc: linux-kernel@vger.kernel.org, mingo@kernel.org, jiangshanlai@gmail.com, dipankar@in.ibm.com, akpm@linux-foundation.org, mathieu.desnoyers@efficios.com, tglx@linutronix.de, peterz@infradead.org, rostedt@goodmis.org, dhowells@redhat.com, edumazet@google.com, fweisbec@gmail.com, oleg@redhat.com, bobby.prani@gmail.com Subject: Re: [PATCH v2 tip/core/rcu 02/11] lockdep: Use "WARNING" tag on lockdep splats Reply-To: paulmck@linux.vnet.ibm.com References: <20170417232714.GA19013@linux.vnet.ibm.com> <1492471738-1377-2-git-send-email-paulmck@linux.vnet.ibm.com> <20170419150022.GB17080@cloud> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20170419150022.GB17080@cloud> User-Agent: Mutt/1.5.21 (2010-09-15) X-TM-AS-GCONF: 00 x-cbid: 17041916-0052-0000-0000-000001DDA6FA X-IBM-SpamModules-Scores: X-IBM-SpamModules-Versions: BY=3.00006939; HX=3.00000240; KW=3.00000007; PH=3.00000004; SC=3.00000208; SDB=6.00849672; UDB=6.00419577; IPR=6.00628305; BA=6.00005304; NDR=6.00000001; ZLA=6.00000005; ZF=6.00000009; ZB=6.00000000; ZP=6.00000000; ZH=6.00000000; ZU=6.00000002; MB=3.00015095; XFM=3.00000013; UTC=2017-04-19 16:26:14 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17041916-0053-0000-0000-0000501264BD Message-Id: <20170419162610.GT3956@linux.vnet.ibm.com> X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:,, definitions=2017-04-19_14:,, signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 spamscore=0 suspectscore=0 malwarescore=0 phishscore=0 adultscore=0 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1703280000 definitions=main-1704190137 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 11487 Lines: 254 On Wed, Apr 19, 2017 at 08:00:22AM -0700, Josh Triplett wrote: > On Mon, Apr 17, 2017 at 04:28:49PM -0700, Paul E. McKenney wrote: > > 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 > > Reported-by: Ingo Molnar > > Signed-off-by: Paul E. McKenney > > Acked-by: Dmitry Vyukov > > Reviewed-by: Josh Triplett Thank you! > Any reason not to change the adjacent calls to printk (without a > priority) to pr_warn? There was some discussion of changing them all throughout the file, not sure where we left that. Thanx, Paul > > kernel/locking/lockdep.c | 86 +++++++++++++++++++++--------------------- > > kernel/locking/rtmutex-debug.c | 9 +++-- > > 2 files changed, 48 insertions(+), 47 deletions(-) > > > > diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c > > index a95e5d1f4a9c..e9d4f85b290c 100644 > > --- a/kernel/locking/lockdep.c > > +++ b/kernel/locking/lockdep.c > > @@ -1144,10 +1144,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); > > @@ -1482,11 +1482,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, > > @@ -1711,10 +1711,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); > > @@ -2061,10 +2061,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"); > > > > @@ -2360,10 +2360,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]); > > @@ -2425,10 +2425,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); > > @@ -3170,10 +3170,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); > > @@ -3383,10 +3383,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); > > @@ -3880,10 +3880,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); > > @@ -4244,10 +4244,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); > > @@ -4302,11 +4302,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(); > > @@ -4371,7 +4371,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); > > @@ -4401,10 +4401,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); > > @@ -4421,13 +4421,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 97ee9df32e0f..db4f55211b04 100644 > > --- a/kernel/locking/rtmutex-debug.c > > +++ b/kernel/locking/rtmutex-debug.c > > @@ -102,10 +102,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)); > > -- > > 2.5.2 > > >