From patchwork Tue Aug 15 15:47:43 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Paul E. McKenney" X-Patchwork-Id: 9902139 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id CA4C860244 for ; Tue, 15 Aug 2017 15:49:18 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id B9E9C252D5 for ; Tue, 15 Aug 2017 15:49:18 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id AE8E227F10; Tue, 15 Aug 2017 15:49:18 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-2.6 required=2.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,RCVD_IN_DNSWL_LOW autolearn=ham version=3.3.1 Received: from bombadil.infradead.org (bombadil.infradead.org [65.50.211.133]) (using TLSv1.2 with cipher AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id EFE37252D5 for ; Tue, 15 Aug 2017 15:49:17 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=lists.infradead.org; s=bombadil.20170209; h=Sender: Content-Transfer-Encoding:Content-Type:Cc:Reply-To:List-Subscribe:List-Help: List-Post:List-Archive:List-Unsubscribe:List-Id:Message-Id:In-Reply-To: MIME-Version:References:Subject:To:From:Date:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: List-Owner; bh=sEo4EN3iwu+Xc7oU8yxx6mz85LvmfRvnZzZIeYWrQM0=; b=KU4wA2Kjdsw76/ NhT4ym7D5C4QiRPA558+uDOx+MT/mqxYpYKEyTDtV4Pnsnfjmii7x+B9OIPSUKl8Uq7DYvM9Coxvk etjex1+a49gvAVfjkMEMNFSwRWY5luJSWBgFeIadO9V2vMZmAdaeDWI92yyf0X4CvUQ9W/DAc8RpH sgG0SFjkixZu3KDE+w3olkLnxcELBVL0Ar46nvnfpERJervU2dOnFVdTY2DOBdA1HUAVeSMqSgscT yd9AR0diN21+FwKP8S9nq0yoJApSZ0zgn81vhk7+JwotVWhazgQxCpzuX+tY4RblW65+y6YU35dqu nQuUysuo/qdDwn6Wuogg==; Received: from localhost ([127.0.0.1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.87 #1 (Red Hat Linux)) id 1dhe5g-0006pq-Ld; Tue, 15 Aug 2017 15:49:12 +0000 Received: from mx0b-001b2d01.pphosted.com ([148.163.158.5] helo=mx0a-001b2d01.pphosted.com) by bombadil.infradead.org with esmtps (Exim 4.87 #1 (Red Hat Linux)) id 1dhe4h-00066f-EN for linux-arm-kernel@lists.infradead.org; Tue, 15 Aug 2017 15:48:55 +0000 Received: from pps.filterd (m0098421.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.21/8.16.0.21) with SMTP id v7FFjiI8023033 for ; Tue, 15 Aug 2017 11:47:48 -0400 Received: from e16.ny.us.ibm.com (e16.ny.us.ibm.com [129.33.205.206]) by mx0a-001b2d01.pphosted.com with ESMTP id 2cc3eds9x1-1 (version=TLSv1.2 cipher=AES256-SHA bits=256 verify=NOT) for ; Tue, 15 Aug 2017 11:47:48 -0400 Received: from localhost by e16.ny.us.ibm.com with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted for from ; Tue, 15 Aug 2017 11:47:47 -0400 Received: from b01cxnp23033.gho.pok.ibm.com (9.57.198.28) by e16.ny.us.ibm.com (146.89.104.203) with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted; Tue, 15 Aug 2017 11:47:43 -0400 Received: from b01ledav003.gho.pok.ibm.com (b01ledav003.gho.pok.ibm.com [9.57.199.108]) by b01cxnp23033.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id v7FFlhIL2359638; Tue, 15 Aug 2017 15:47:43 GMT Received: from b01ledav003.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id BB4CCB2046; Tue, 15 Aug 2017 11:45:08 -0400 (EDT) Received: from paulmck-ThinkPad-W541 (unknown [9.70.82.146]) by b01ledav003.gho.pok.ibm.com (Postfix) with ESMTP id 703E8B204D; Tue, 15 Aug 2017 11:45:08 -0400 (EDT) Received: by paulmck-ThinkPad-W541 (Postfix, from userid 1000) id 3941016C2EC2; Tue, 15 Aug 2017 08:47:43 -0700 (PDT) Date: Tue, 15 Aug 2017 08:47:43 -0700 From: "Paul E. McKenney" To: Jonathan Cameron Subject: Re: RCU lockup issues when CONFIG_SOFTLOCKUP_DETECTOR=n - any one else seeing this? References: <20170728084411.00001ddb@huawei.com> <20170728142403.0000122b@huawei.com> <20170728165529.GF3730@linux.vnet.ibm.com> <20170728182053.000072aa@huawei.com> <20170728190349.GM3730@linux.vnet.ibm.com> <20170731120847.00003d5c@huawei.com> <20170731150411.GA3730@linux.vnet.ibm.com> <20170731162757.000058ba@huawei.com> <20170801184646.GE3730@linux.vnet.ibm.com> <20170802172555.0000468a@huawei.com> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20170802172555.0000468a@huawei.com> User-Agent: Mutt/1.5.21 (2010-09-15) X-TM-AS-GCONF: 00 x-cbid: 17081515-0024-0000-0000-000002BFF61B X-IBM-SpamModules-Scores: X-IBM-SpamModules-Versions: BY=3.00007549; HX=3.00000241; KW=3.00000007; PH=3.00000004; SC=3.00000221; SDB=6.00902720; UDB=6.00452147; IPR=6.00682935; BA=6.00005534; NDR=6.00000001; ZLA=6.00000005; ZF=6.00000009; ZB=6.00000000; ZP=6.00000000; ZH=6.00000000; ZU=6.00000002; MB=3.00016706; XFM=3.00000015; UTC=2017-08-15 15:47:46 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17081515-0025-0000-0000-0000451B167A Message-Id: <20170815154743.GK7017@linux.vnet.ibm.com> X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:, , definitions=2017-08-15_12:, , 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-1706020000 definitions=main-1708150266 X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20170815_084812_180065_FECFDC64 X-CRM114-Status: GOOD ( 42.45 ) X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Reply-To: paulmck@linux.vnet.ibm.com Cc: dzickus@redhat.com, sfr@canb.auug.org.au, linuxarm@huawei.com, Nicholas Piggin , abdhalee@linux.vnet.ibm.com, tglx@linutronix.de, sparclinux@vger.kernel.org, akpm@linux-foundation.org, linuxppc-dev@lists.ozlabs.org, David Miller , linux-arm-kernel@lists.infradead.org Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+patchwork-linux-arm=patchwork.kernel.org@lists.infradead.org X-Virus-Scanned: ClamAV using ClamSMTP On Wed, Aug 02, 2017 at 05:25:55PM +0100, Jonathan Cameron wrote: > On Tue, 1 Aug 2017 11:46:46 -0700 > "Paul E. McKenney" wrote: > > > On Mon, Jul 31, 2017 at 04:27:57PM +0100, Jonathan Cameron wrote: > > > On Mon, 31 Jul 2017 08:04:11 -0700 > > > "Paul E. McKenney" wrote: > > > > > > > On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote: > > > > > On Fri, 28 Jul 2017 12:03:50 -0700 > > > > > "Paul E. McKenney" wrote: > > > > > > > > > > > On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote: > > > > > > > On Fri, 28 Jul 2017 09:55:29 -0700 > > > > > > > "Paul E. McKenney" wrote: > > > > > > > > > > > > > > > On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote: > > > > > > > > > On Fri, 28 Jul 2017 08:44:11 +0100 > > > > > > > > > Jonathan Cameron wrote: > > > > > > > > > > > > > > > > [ . . . ] > > > > > > > > > > > > > > > > > Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having > > > > > > > > > fewer timer events. Issue became much easier to trigger (on some runs before > > > > > > > > > I could get tracing up and running) > > > > > > > > >e > > > > > > > > > So logs are large enough that pastebin doesn't like them - please shoet if > > > > > > > > >>e another timer period is of interest. > > > > > > > > > > > > > > > > > > https://pastebin.com/iUZDfQGM for the timer trace. > > > > > > > > > https://pastebin.com/3w1F7amH for dmesg. > > > > > > > > > > > > > > > > > > The relevant timeout on the RCU stall detector was 8 seconds. Event is > > > > > > > > > detected around 835. > > > > > > > > > > > > > > > > > > It's a lot of logs, so I haven't identified a smoking gun yet but there > > > > > > > > > may well be one in there. > > > > > > > > > > > > > > > > The dmesg says: > > > > > > > > > > > > > > > > rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > > > > > > > > > > > > > > > > So I look for "rcu_preempt" timer events and find these: > > > > > > > > > > > > > > > > rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0 > > > > > > > > rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout > > > > > > > > > > > > > > > > Next look for "ffff8017d5fc7da0" and I don't find anything else. > > > > > > > It does show up off the bottom of what would fit in pastebin... > > > > > > > > > > > > > > rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0 > > > > > > > rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0 > > > > > > > rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags= > > > > > > > > > > > > Odd. I would expect an expiration... And ten seconds is way longer > > > > > > than the requested one jiffy! > > > > > > > > > > > > > > The timeout was one jiffy, and more than a second later, no expiration. > > > > > > > > Is it possible that this event was lost? I am not seeing any sign of > > > > > > > > this is the trace. > > > > > > > > > > > > > > > > I don't see any sign of CPU hotplug (and I test with lots of that in > > > > > > > > any case). > > > > > > > > > > > > > > > > The last time we saw something like this it was a timer HW/driver problem, > > > > > > > > but it is a bit hard to imagine such a problem affecting both ARM64 > > > > > > > > and SPARC. ;-) > > > > > > > Could be different issues, both of which were hidden by that lockup detector. > > > > > > > > > > > > > > There is an errata work around for the timers on this particular board. > > > > > > > I'm only vaguely aware of it, so may be unconnected. > > > > > > > > > > > > > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/drivers/clocksource/arm_arch_timer.c?h=v4.13-rc2&id=bb42ca47401010fc02901b5e8f79e40a26f208cb > > > > > > > > > > > > > > Seems unlikely though! + we've not yet seen it on the other chips that > > > > > > > errata effects (not that that means much). > > > > > > > > > > > > If you can reproduce quickly, might be worth trying anyway... > > > > > > > > > > > > Thanx, Paul > > > > > Errata fix is running already and was for all those tests. > > > > > > > > I was afraid of that... ;-) > > > It's a pretty rare errata it seems. Not actually managed to catch > > > one yet. > > > > > > > > > I'll have a dig into the timers today and see where I get to. > > > > > > > > Look forward to seeing what you find! > > > Nothing obvious turning up other than we don't seem to have issue > > > when we aren't running hrtimers. > > > > > > On a plus side I just got a report that it is effecting our d03 > > > boards which is good on the basis I couldn't tell what the difference > > > could be wrt to this issue! > > > > > > It indeed looks like we are consistently missing a timer before > > > the rcu splat occurs. > > > > And for my part, my tests with CONFIG_HZ_PERIODIC=y and > > CONFIG_RCU_FAST_NO_HZ=n showed roughly the same failure rate > > as other runs. > > > > Missing a timer can most certainly give RCU severe heartburn! ;-) > > Do you have what you need to track down the missing timer? > > Not managed to make much progress yet. Turning on any additional tracing > in that area seems to make the issue stop happening or at least > occur very infrequently. Which certainly makes it 'fun' to find. > > As a long shot I applied a locking fix from another reported issue that > was causing rcu stalls and it seemed good for much longer, but > eventually still occurred. > > (from the thread rcu_sched stall while waiting in csd_lock_wait()) On the perhaps unlikely off-chance that it helps locate something, here is a patch that adds a trace_printk() to check how long a CPU believes that it can sleep when going idle. The thought is to check to see if a CPU with a timer set to expire in one jiffy thinks that can sleep for (say) 30 seconds. Didn't find anything for my problem, but I believe that yours is different, so... Thanx, Paul ------------------------------------------------------------------------ commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312 Author: Paul E. McKenney Date: Mon Aug 14 08:54:39 2017 -0700 EXP: Trace tick return from tick_nohz_stop_sched_tick Signed-off-by: Paul E. McKenney diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c index c7a899c5ce64..7358a5073dfb 100644 --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -817,6 +817,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts, * (not only the tick). */ ts->sleep_length = ktime_sub(dev->next_event, now); + trace_printk("tick_nohz_stop_sched_tick: %lld\n", (tick - ktime_get()) / 1000); return tick; }