From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755875AbcG0M0n (ORCPT ); Wed, 27 Jul 2016 08:26:43 -0400 Received: from aserp1040.oracle.com ([141.146.126.69]:19802 "EHLO aserp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754131AbcG0M0l (ORCPT ); Wed, 27 Jul 2016 08:26:41 -0400 Subject: Re: [PATCH] sched/core: make "Preemption disabled at" message more useful To: Ingo Molnar , Vegard Nossum References: <1469260693-22260-1-git-send-email-vegard.nossum@oracle.com> <20160727091527.GB6323@gmail.com> <20160727103814.GB8845@gmail.com> Cc: Ingo Molnar , Peter Zijlstra , LKML , "Paul E. McKenney" , Thomas Gleixner , Rusty Russel From: Vegard Nossum Message-ID: <5798A84E.70806@oracle.com> Date: Wed, 27 Jul 2016 14:25:50 +0200 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.8.0 MIME-Version: 1.0 In-Reply-To: <20160727103814.GB8845@gmail.com> Content-Type: multipart/mixed; boundary="------------050401090507090307060405" X-Source-IP: aserv0022.oracle.com [141.146.126.234] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org This is a multi-part message in MIME format. --------------050401090507090307060405 Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit On 07/27/2016 12:38 PM, Ingo Molnar wrote: > * Vegard Nossum wrote: >> I'm assuming you want to declare and initialise preempt_disable_ip at >> once here, but it generates slightly worse code since it dereferences >> current->preempt_disable_ip in the "fast path" (i.e. a sleeping >> function is NOT called from an invalid context). > > Could you please add a likely() branch to see whether GCC will delay the > initialization? > > The 4 #ifdefs were really ugly, so yes, it would be nice to at least reduce them > to 2. How about this? Vegard --------------050401090507090307060405 Content-Type: text/x-patch; name="0001-sched-core-make-Preemption-disabled-at-message-more-.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename*0="0001-sched-core-make-Preemption-disabled-at-message-more-.pa"; filename*1="tch" >>From 9d0e4bb63f0fada627a4f99432db8d39add487b4 Mon Sep 17 00:00:00 2001 From: Vegard Nossum Date: Sat, 23 Jul 2016 09:46:39 +0200 Subject: [PATCH] sched/core: make "Preemption disabled at" message more useful This message is currently really useless since it always prints a value that comes from the printk() we just did, e.g.: BUG: sleeping function called from invalid context at mm/slab.h:388 in_atomic(): 0, irqs_disabled(): 0, pid: 31996, name: trinity-c1 Preemption disabled at:[] down_trylock+0x13/0x80 BUG: sleeping function called from invalid context at include/linux/freezer.h:56 in_atomic(): 0, irqs_disabled(): 0, pid: 31996, name: trinity-c1 Preemption disabled at:[] console_unlock+0x2f7/0x930 Here, both down_trylock() and console_unlock() is somewhere in the printk() path. We should save the value before calling printk() and use the saved value instead. That immediately reveals the offending callsite: BUG: sleeping function called from invalid context at mm/slab.h:388 in_atomic(): 0, irqs_disabled(): 0, pid: 14971, name: trinity-c2 Preemption disabled at:[] rhashtable_walk_start+0x46/0x150 (Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2) Cc: Peter Zijlstra Cc: Paul E. McKenney Cc: Thomas Gleixner Cc: Ingo Molnar Cc: Rusty Russel Signed-off-by: Vegard Nossum --- include/linux/sched.h | 9 +++++++++ kernel/sched/core.c | 21 +++++++++++++-------- 2 files changed, 22 insertions(+), 8 deletions(-) diff --git a/include/linux/sched.h b/include/linux/sched.h index 253538f2..cdbcc2e 100644 --- a/include/linux/sched.h +++ b/include/linux/sched.h @@ -3142,6 +3142,15 @@ static inline void cond_resched_rcu(void) #endif } +static inline unsigned long get_preempt_disable_ip(struct task_struct *p) +{ +#ifdef CONFIG_DEBUG_PREEMPT + return p->preempt_disable_ip; +#else + return 0; +#endif +} + /* * Does a critical section need to be broken due to another * task waiting?: (technically does not depend on CONFIG_PREEMPT, diff --git a/kernel/sched/core.c b/kernel/sched/core.c index 7171cf9..afd2403 100644 --- a/kernel/sched/core.c +++ b/kernel/sched/core.c @@ -3144,6 +3144,9 @@ static inline void preempt_latency_stop(int val) { } */ static noinline void __schedule_bug(struct task_struct *prev) { + /* Save this before calling printk(), since that will clobber it */ + unsigned long preempt_disable_ip = get_preempt_disable_ip(current); + if (oops_in_progress) return; @@ -3154,13 +3157,12 @@ static noinline void __schedule_bug(struct task_struct *prev) print_modules(); if (irqs_disabled()) print_irqtrace_events(prev); -#ifdef CONFIG_DEBUG_PREEMPT - if (in_atomic_preempt_off()) { + if (IS_ENABLED(CONFIG_DEBUG_PREEMPT) + && in_atomic_preempt_off()) { pr_err("Preemption disabled at:"); - print_ip_sym(current->preempt_disable_ip); + print_ip_sym(preempt_disable_ip); pr_cont("\n"); } -#endif dump_stack(); add_taint(TAINT_WARN, LOCKDEP_STILL_OK); } @@ -7541,6 +7543,7 @@ EXPORT_SYMBOL(__might_sleep); void ___might_sleep(const char *file, int line, int preempt_offset) { static unsigned long prev_jiffy; /* ratelimiting */ + unsigned long preempt_disable_ip; rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */ if ((preempt_count_equals(preempt_offset) && !irqs_disabled() && @@ -7551,6 +7554,9 @@ void ___might_sleep(const char *file, int line, int preempt_offset) return; prev_jiffy = jiffies; + /* Save this before calling printk(), since that will clobber it */ + preempt_disable_ip = get_preempt_disable_ip(current); + printk(KERN_ERR "BUG: sleeping function called from invalid context at %s:%d\n", file, line); @@ -7565,13 +7571,12 @@ void ___might_sleep(const char *file, int line, int preempt_offset) debug_show_held_locks(current); if (irqs_disabled()) print_irqtrace_events(current); -#ifdef CONFIG_DEBUG_PREEMPT - if (!preempt_count_equals(preempt_offset)) { + if (IS_ENABLED(CONFIG_DEBUG_PREEMPT) + && !preempt_count_equals(preempt_offset)) { pr_err("Preemption disabled at:"); - print_ip_sym(current->preempt_disable_ip); + print_ip_sym(preempt_disable_ip); pr_cont("\n"); } -#endif dump_stack(); add_taint(TAINT_WARN, LOCKDEP_STILL_OK); } -- 1.9.1 --------------050401090507090307060405--