linux-kernel - RE: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:	Fri, 25 Mar 2016 21:24:14 +0000
From:	"Chatre, Reinette" <reinette.chatre@...el.com>
To:	"paulmck@...ux.vnet.ibm.com" <paulmck@...ux.vnet.ibm.com>
CC:	Jacob Pan <jacob.jun.pan@...ux.intel.com>,
	Josh Triplett <josh@...htriplett.org>,
	Ross Green <rgkernel@...il.com>,
	Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
	John Stultz <john.stultz@...aro.org>,
	Thomas Gleixner <tglx@...utronix.de>,
	Peter Zijlstra <peterz@...radead.org>,
	lkml <linux-kernel@...r.kernel.org>,
	Ingo Molnar <mingo@...nel.org>,
	"Lai Jiangshan" <jiangshanlai@...il.com>,
	"dipankar@...ibm.com" <dipankar@...ibm.com>,
	Andrew Morton <akpm@...ux-foundation.org>,
	rostedt <rostedt@...dmis.org>,
	David Howells <dhowells@...hat.com>,
	Eric Dumazet <edumazet@...gle.com>,
	Darren Hart <dvhart@...ux.intel.com>,
	Frédéric Weisbecker <fweisbec@...il.com>,
	Oleg Nesterov <oleg@...hat.com>,
	pranith kumar <bobby.prani@...il.com>
Subject: RE: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17

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. 

[  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]  [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310
[  957.431713]  [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20
[  957.435122]  [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40
[  957.438467]  [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360
[  957.441949]  [<ffffffff8108c864>] ? 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]  [<ffffffff81ab03df>] schedule+0x3f/0xa0
[  957.470613]  [<ffffffff81ab4397>] schedule_timeout+0x127/0x270
[  957.473976]  [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120
[  957.477387]  [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40
[  957.480659]  [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70
[  957.484123]  [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0
[  957.487392]  [<ffffffff8112f856>] kthread+0xe6/0x100
[  957.490470]  [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
[  957.493859]  [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70
[  957.497044]  [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190

Reinette

Download attachment "trace.trim.gz" of type "application/x-gzip" (55975 bytes)