From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753117AbdK1RJO (ORCPT ); Tue, 28 Nov 2017 12:09:14 -0500 Received: from mx0b-001b2d01.pphosted.com ([148.163.158.5]:49178 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752309AbdK1RJN (ORCPT ); Tue, 28 Nov 2017 12:09:13 -0500 Date: Tue, 28 Nov 2017 09:07:59 -0800 From: "Paul E. McKenney" To: Thomas Gleixner Cc: kernel test robot , LKML , lkp@01.org Subject: Re: [lkp-robot] [torture] b151f93a71: INFO:rcu_preempt_detected_stalls_on_CPUs/tasks Reply-To: paulmck@linux.vnet.ibm.com References: <20171126084203.GE21779@yexl-desktop> <20171127215735.GP3624@linux.vnet.ibm.com> <20171128164144.GS3624@linux.vnet.ibm.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.21 (2010-09-15) X-TM-AS-GCONF: 00 x-cbid: 17112817-0040-0000-0000-000003C95CEE X-IBM-SpamModules-Scores: X-IBM-SpamModules-Versions: BY=3.00008121; HX=3.00000241; KW=3.00000007; PH=3.00000004; SC=3.00000242; SDB=6.00952505; UDB=6.00481189; IPR=6.00732586; BA=6.00005719; NDR=6.00000001; ZLA=6.00000005; ZF=6.00000009; ZB=6.00000000; ZP=6.00000000; ZH=6.00000000; ZU=6.00000002; MB=3.00018227; XFM=3.00000015; UTC=2017-11-28 17:08:01 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17112817-0041-0000-0000-000007BE895E Message-Id: <20171128170759.GU3624@linux.vnet.ibm.com> X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:,, definitions=2017-11-28_10:,, 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-1709140000 definitions=main-1711280231 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Nov 28, 2017 at 05:47:35PM +0100, Thomas Gleixner wrote: > On Tue, 28 Nov 2017, Paul E. McKenney wrote: > > > On Tue, Nov 28, 2017 at 03:16:30PM +0100, Thomas Gleixner wrote: > > > On Mon, 27 Nov 2017, Paul E. McKenney wrote: > > > > On Sun, Nov 26, 2017 at 04:42:03PM +0800, kernel test robot wrote: > > > > > [ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 > > > > > > > > So the immediate reason for the stall warning is that the RCU grace-period > > > > kthread isn't being allowed to run. > > > > > > > > > [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 > > > > > [ 116.356543] Call Trace: > > > > > [ 116.357008] __schedule+0x493/0x620 > > > > > [ 116.357682] schedule+0x24/0x40 > > > > > [ 116.358291] schedule_timeout+0x330/0x3b0 > > > > > > > > And the reason that it isn't being allowed to run is that its few-jiffy > > > > schedule_timeout has extended for more than nine thousand jiffies. > > > > > > > > There was an odd combination of kernel parameters that Thomas Gleixner > > > > came across that could cause writer-thread stalls (since fixed in -rcu > > > > by the exact patch you call out here), but I don't see how this could > > > > cause an RCU CPU stall warning. > > > > > > > > > > > > The only reasonable explanation is that either a wakeup is missed or the > > > timer is not expired. Hard to tell from that back trace, but it would be > > > interesting to figure that out. Let me think about how that can be done. > > > > Please see below for my latest patch in service of futility. It leverages > > the fact that the stall-warning code takes the desperation step of sending > > an unsolicited wakeup to the grace-period kthread. This allows the patch > > to use a stupid but effective heuristic to detect that the timer (or the > > wakeup) has gone AWOL. > > > > I get the following "Waylayed timer" line from it: > > > > [ 8015.327554] rcu_sched kthread starved for 21096 jiffies! g12440 c12439 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=3 > > [ 8015.327554] rcu_sched I14992 9 2 0x80000000 > > [ 8015.327554] Call Trace: > > [ 8015.327554] ? __schedule+0x33c/0x6f0 > > [ 8015.327554] ? preempt_count_add+0x51/0x90 > > [ 8015.327554] schedule+0x37/0x90 > > [ 8015.327554] schedule_timeout+0x159/0x410 > > [ 8015.327554] ? __next_timer_interrupt+0xc0/0xc0 > > [ 8015.327554] rcu_gp_kthread+0xa42/0x1080 > > [ 8015.327554] kthread+0xf0/0x130 > > [ 8015.327554] ? rcu_barrier+0x10/0x10 > > [ 8015.327554] ? kthread_destroy_worker+0x40/0x40 > > [ 8015.327554] ret_from_fork+0x1f/0x30 > > [ 8015.421044] schedule_timeout: Waylayed timer idx: 56 idx_now: 222 > > > > Is there something more useful that I could make this thing print? > > Please let it print base->clk, jiffies, base->next_expiry, timer->flags, > and timer->expires. Like this, on top of the previous patch? Thanx, Paul ------------------------------------------------------------------------ commit 1085cc784fe1e9d4b5e3bb2f849c0a7fa47b7cb7 Author: Paul E. McKenney Date: Tue Nov 28 09:05:39 2017 -0800 EXP: timer: Dump more info if timer misses by huge amount "Please let it print base->clk, jiffies, base->next_expiry, timer->flags, and timer->expires." Suggested-by: Thomas Gleixner Signed-off-by: Paul E. McKenney diff --git a/kernel/time/timer.c b/kernel/time/timer.c index db774b0f217e..a3321bb565db 100644 --- a/kernel/time/timer.c +++ b/kernel/time/timer.c @@ -1803,7 +1803,7 @@ signed long __sched schedule_timeout(signed long timeout) idx = timer_get_idx(&timer.timer); idx_now = calc_wheel_index(j, base->clk); raw_spin_unlock_irqrestore(&base->lock, flags); - pr_info("%s: Waylayed timer idx: %u idx_now: %u\n", __func__, idx, idx_now); + pr_info("%s: Waylayed timer base->clk: %#lx jiffies: %#lx base->next_expiry: %#lx timer->flags: %#x timer->expires %#lx idx: %u idx_now: %u\n", __func__, base->clk, j, base->next_expiry, timer.timer.flags, timer.timer.expires, idx, idx_now); } del_singleshot_timer_sync(&timer.timer);