From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753759AbdK1RgD (ORCPT ); Tue, 28 Nov 2017 12:36:03 -0500 Received: from mx0b-001b2d01.pphosted.com ([148.163.158.5]:35354 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752794AbdK1RgA (ORCPT ); Tue, 28 Nov 2017 12:36:00 -0500 Date: Tue, 28 Nov 2017 09:35:54 -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> <20171128170759.GU3624@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-0024-0000-0000-000002F95FFD 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.00952514; UDB=6.00481195; IPR=6.00732595; 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:35:57 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17112817-0025-0000-0000-000046299A68 Message-Id: <20171128173554.GV3624@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 priorityscore=1501 malwarescore=0 suspectscore=0 phishscore=0 bulkscore=0 spamscore=0 clxscore=1015 lowpriorityscore=0 impostorscore=0 adultscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1709140000 definitions=main-1711280236 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Nov 28, 2017 at 06:10:08PM +0100, Thomas Gleixner wrote: > On Tue, 28 Nov 2017, Paul E. McKenney wrote: > > On Tue, Nov 28, 2017 at 05:47:35PM +0100, Thomas Gleixner wrote: > > 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); > > Please print idx and idx_now as hex values. It's simpler to decode that way. Here you go! Starting tests at this end, focusing on TREE01 and TREE04. BTW, TREE04 doesn't do any CPU hotplug, providing a counterexample to my long-held assumption that this only happened in the presence of CPU hotplug operations. Thanx, Paul ------------------------------------------------------------------------ commit dfdfd710624e66b48de829f5302dadbc619c0885 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..fac6704cdb18 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: %x idx_now: %x\n", __func__, base->clk, j, base->next_expiry, timer.timer.flags, timer.timer.expires, idx, idx_now); } del_singleshot_timer_sync(&timer.timer); From mboxrd@z Thu Jan 1 00:00:00 1970 Content-Type: multipart/mixed; boundary="===============6901843796313539688==" MIME-Version: 1.0 From: Paul E. McKenney To: lkp@lists.01.org Subject: Re: [lkp-robot] [torture] b151f93a71: INFO:rcu_preempt_detected_stalls_on_CPUs/tasks Date: Tue, 28 Nov 2017 09:35:54 -0800 Message-ID: <20171128173554.GV3624@linux.vnet.ibm.com> In-Reply-To: List-Id: --===============6901843796313539688== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable On Tue, Nov 28, 2017 at 06:10:08PM +0100, Thomas Gleixner wrote: > On Tue, 28 Nov 2017, Paul E. McKenney wrote: > > On Tue, Nov 28, 2017 at 05:47:35PM +0100, Thomas Gleixner wrote: > > 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 =3D timer_get_idx(&timer.timer); > > idx_now =3D 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, i= dx_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); > = > Please print idx and idx_now as hex values. It's simpler to decode that w= ay. Here you go! Starting tests at this end, focusing on TREE01 and TREE04. BTW, TREE04 doesn't do any CPU hotplug, providing a counterexample to my long-held assumption that this only happened in the presence of CPU hotplug operations. Thanx, Paul ------------------------------------------------------------------------ commit dfdfd710624e66b48de829f5302dadbc619c0885 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->flag= s, 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..fac6704cdb18 100644 --- a/kernel/time/timer.c +++ b/kernel/time/timer.c @@ -1803,7 +1803,7 @@ signed long __sched schedule_timeout(signed long time= out) idx =3D timer_get_idx(&timer.timer); idx_now =3D 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_n= ow); + pr_info("%s: Waylayed timer base->clk: %#lx jiffies: %#lx base->next_exp= iry: %#lx timer->flags: %#x timer->expires %#lx idx: %x idx_now: %x\n", __f= unc__, base->clk, j, base->next_expiry, timer.timer.flags, timer.timer.expi= res, idx, idx_now); } del_singleshot_timer_sync(&timer.timer); = --===============6901843796313539688==--