Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754367AbcCYVqU (ORCPT ); Fri, 25 Mar 2016 17:46:20 -0400 Received: from e31.co.us.ibm.com ([32.97.110.149]:57264 "EHLO e31.co.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753273AbcCYVqT (ORCPT ); Fri, 25 Mar 2016 17:46:19 -0400 X-IBM-Helo: d03dlp03.boulder.ibm.com X-IBM-MailFrom: paulmck@linux.vnet.ibm.com X-IBM-RcptTo: linux-kernel@vger.kernel.org Date: Fri, 25 Mar 2016 14:46:23 -0700 From: "Paul E. McKenney" To: "Chatre, Reinette" Cc: Jacob Pan , Josh Triplett , Ross Green , Mathieu Desnoyers , John Stultz , Thomas Gleixner , Peter Zijlstra , lkml , Ingo Molnar , Lai Jiangshan , "dipankar@in.ibm.com" , Andrew Morton , rostedt , David Howells , Eric Dumazet , Darren Hart , =?iso-8859-1?Q?Fr=E9d=E9ric?= Weisbecker , Oleg Nesterov , pranith kumar Subject: Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Message-ID: <20160325214623.GR4287@linux.vnet.ibm.com> Reply-To: paulmck@linux.vnet.ibm.com References: <20160318235641.GH4287@linux.vnet.ibm.com> <20160321092230.75f23fa9@yairi> <20160321172616.GU4287@linux.vnet.ibm.com> <0D818C7A2259ED42912C1E04120FDE26712E27C8@ORSMSX111.amr.corp.intel.com> <20160322174011.GM4287@linux.vnet.ibm.com> <0D818C7A2259ED42912C1E04120FDE26712E3DF3@ORSMSX111.amr.corp.intel.com> <20160322211939.GT4287@linux.vnet.ibm.com> <0D818C7A2259ED42912C1E04120FDE26712E4559@ORSMSX111.amr.corp.intel.com> <20160323182055.GG4287@linux.vnet.ibm.com> <0D818C7A2259ED42912C1E04120FDE26712E676E@ORSMSX111.amr.corp.intel.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <0D818C7A2259ED42912C1E04120FDE26712E676E@ORSMSX111.amr.corp.intel.com> User-Agent: Mutt/1.5.21 (2010-09-15) X-TM-AS-MML: disable X-Content-Scanned: Fidelis XPS MAILER x-cbid: 16032521-8236-0000-0000-00001BA73FD5 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 3983 Lines: 59 On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: > Hi Paul, > > On 2016-03-23, Paul E. McKenney wrote: > > Please boot with the following parameters: > > > > rcu_tree.rcu_kick_kthreads ftrace > > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > With these parameters I expected more details to show up in the kernel logs but cannot find any. Even so, today I left the machine running again and when this happened I think I was able to capture the trace data for the event. Please find attached the trace information for the kernel message below. Since the complete trace file is very big I trimmed it to show the time around this event - hopefully this will contain the information you need. I would also like to provide some additional information. The system on which I see these events had a time that was _very_ wrong. I noticed that this issue occurs when system-timesynd was one of the tasks calling the functions of interest to your tracing and am wondering if a very out of sync time in process of being corrected could be the cause of this issue? As an experiment I ensured the system time was accurate before leaving the system idle overnight and I did not see the issue the next morning. Ah! Yes, a sudden jump in time or a disagreement about the time among different components of the system can definitely cause these symptoms. We have sometimes seen these problems occur when a pair of CPUs have wildly different ideas about what time it is, for example. Please let me know how it goes. Also, in your trace, there are no sched_waking events for the rcu_preempt process that are not immediately followed by sched_wakeup, so your trace isn't showing the problem that I am seeing. Still beating up on my stress test, which is not yet proving to be all that stressful. :-/ Thanx, Paul > [ 957.396537] INFO: rcu_preempt detected stalls on CPUs/tasks: > [ 957.399933] 1-...: (0 ticks this GP) idle=4d6/0/0 softirq=6311/6311 fqs=0 > [ 957.403661] (detected by 0, t=60002 jiffies, g=3583, c=3582, q=47) > [ 957.407227] Task dump for CPU 1: > [ 957.409964] swapper/1 R running task 0 0 1 0x00200000 > [ 957.413770] 0000039daa9a7eb9 ffff8801785cfed0 ffffffff818af34c ffff880100000000 > [ 957.417696] 0000000600000003 ffff8801785d0000 ffff880072f9ea00 ffffffff822dcf80 > [ 957.421631] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0 ffffffff818af597 > [ 957.425562] Call Trace: > [ 957.428124] [] ? cpuidle_enter_state+0xfc/0x310 > [ 957.431713] [] ? cpuidle_enter+0x17/0x20 > [ 957.435122] [] ? call_cpuidle+0x2a/0x40 > [ 957.438467] [] ? cpu_startup_entry+0x28d/0x360 > [ 957.441949] [] ? start_secondary+0x114/0x140 > [ 957.445378] rcu_preempt kthread starved for 60002 jiffies! g3583 c3582 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [ 957.449834] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [ 957.453579] ffff8801785b7d68 ffff88017dc8cc80 ffff88016fe6bb80 ffff8801785abb80 > [ 957.457428] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80 ffff88017dc8cc80 > [ 957.461249] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000100373021 > [ 957.465055] Call Trace: > [ 957.467493] [] schedule+0x3f/0xa0 > [ 957.470613] [] schedule_timeout+0x127/0x270 > [ 957.473976] [] ? detach_if_pending+0x120/0x120 > [ 957.477387] [] rcu_gp_kthread+0x6d3/0xa40 > [ 957.480659] [] ? wake_atomic_t_function+0x70/0x70 > [ 957.484123] [] ? force_qs_rnp+0x1b0/0x1b0 > [ 957.487392] [] kthread+0xe6/0x100 > [ 957.490470] [] ? kthread_worker_fn+0x190/0x190 > [ 957.493859] [] ret_from_fork+0x3f/0x70 > [ 957.497044] [] ? kthread_worker_fn+0x190/0x190 > > Reinette