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
trace.trim.gz
Description: trace.trim.gz
