Re: INFO: rcu_sched self-detected stall on CPU

From: Enrico Mioso
Date: Thu Jan 05 2017 - 13:33:54 EST

Here is a new trace in the meanwhile: reporting it in case it proves useful.
Thank you very much for your help and patience.
Enrico
[34839.019680] INFO: rcu_sched self-detected stall on CPU
[34839.019694] INFO: rcu_sched detected stalls on CPUs/tasks:
[34839.019711] 0-...: (1 GPs behind) idle=3d7/1/0 softirq=5887188/5887188 fqs=0 [34839.019713] [34839.019725] 0-...: (1 GPs behind) idle=3d7/1/0 softirq=5887188/5887188 fqs=0 [34839.019727] [34839.019733] (t=39875 jiffies g=3086597 c=3086596 q=1)
[34839.019744] rcu_sched kthread starved for 39875 jiffies! g3086597 c3086596 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
[34839.019751] (detected by 1, t=39875 jiffies, g=3086597, c=3086596, q=1)
[34839.019755] Task dump for CPU 0:
[34839.019758] rcu_sched S 0 7 2 0x00000000
[34839.019768] swapper/0 R running task [34839.019774] Call Trace:
[34839.019779] 0 0 0 0x00000008
[34839.019783] Call Trace:
[34839.019808] ? cpuidle_enter_state+0x16c/0x350
[34839.019818] ? __schedule+0x155/0x650
[34839.019831] ? _raw_spin_lock_irqsave+0x14/0x40
[34839.019839] ? cpuidle_enter+0x14/0x20
[34839.019850] ? call_cpuidle+0x21/0x40
[34839.019857] schedule+0x2e/0x70
[34839.019866] ? do_idle+0xd3/0x1b0
[34839.019875] schedule_timeout+0x18f/0x350
[34839.019885] ? cpu_startup_entry+0x65/0x70
[34839.019894] ? del_timer_sync+0x60/0x60
[34839.019904] ? rest_init+0x62/0x70
[34839.019914] rcu_gp_kthread+0x575/0xce0
[34839.019927] ? start_kernel+0x32c/0x342
[34839.019935] ? force_qs_rnp+0x170/0x170
[34839.019946] kthread+0xd6/0x110
[34839.019954] ? i386_start_kernel+0x90/0x94
[34839.019963] ? startup_32_smp+0x16b/0x16d
[34839.019971] ? force_qs_rnp+0x170/0x170
[34839.019981] ? kthread_create_on_node+0x30/0x30
[34839.019991] rcu_sched kthread starved for 39875 jiffies! g3086597 c3086596 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
[34839.019995] rcu_sched S
[34839.020004] ret_from_fork+0x19/0x24
[34839.020011] 0 7 2 0x00000000
[34839.020015] Call Trace:
[34839.020029] ? __schedule+0x155/0x650
[34839.020032] Task dump for CPU 0:
[34839.020036] swapper/0 R
[34839.020046] ? _raw_spin_lock_irqsave+0x14/0x40
[34839.020049] running task [34839.020057] schedule+0x2e/0x70
[34839.020063] 0 0 0 0x00000008
[34839.020071] schedule_timeout+0x18f/0x350
[34839.020075] Call Trace:
[34839.020083] ? del_timer_sync+0x60/0x60
[34839.020096] rcu_gp_kthread+0x575/0xce0
[34839.020098] <IRQ>
[34839.020109] sched_show_task+0xf3/0x160
[34839.020117] ? force_qs_rnp+0x170/0x170
[34839.020126] kthread+0xd6/0x110
[34839.020133] dump_cpu_task+0x37/0x40
[34839.020143] ? force_qs_rnp+0x170/0x170
[34839.020153] rcu_dump_cpu_stacks+0x79/0x95
[34839.020164] ? kthread_create_on_node+0x30/0x30
[34839.020172] rcu_check_callbacks+0x621/0x770
[34839.020184] ret_from_fork+0x19/0x24
[34839.020191] ? ttwu_do_activate+0x5f/0x70
[34839.020203] update_process_times+0x28/0x50
[34839.020215] tick_sched_handle.isra.11+0x2f/0x40
[34839.020225] tick_sched_timer+0x3b/0x80
[34839.020236] __hrtimer_run_queues+0xdb/0x2b0
[34839.020247] ? tick_sched_do_timer+0x60/0x60
[34839.020258] hrtimer_interrupt+0x8b/0x180
[34839.020269] ? default_send_IPI_mask_logical+0x5f/0x80
[34839.020281] tick_handle_oneshot_broadcast+0x14c/0x190
[34839.020293] timer_interrupt+0x12/0x20
[34839.020304] __handle_irq_event_percpu+0x78/0x190
[34839.020316] ? add_interrupt_randomness+0x144/0x1a0
[34839.020327] ? handle_level_irq+0xf0/0xf0
[34839.020336] handle_irq_event_percpu+0x2c/0x70
[34839.020346] handle_irq_event+0x27/0x40
[34839.020356] handle_edge_irq+0x5d/0x120
[34839.020366] handle_irq+0x9b/0xc0
[34839.020370] </IRQ>
[34839.020380] do_IRQ+0x3d/0xc0
[34839.020393] common_interrupt+0x3a/0x40
[34839.020405] EIP: cpuidle_enter_state+0x16c/0x350
[34839.020411] EFLAGS: 00200246 CPU: 0
[34839.020418] EAX: 00000000 EBX: f9c80a40 ECX: 4ebd61d5 EDX: 00000000
[34839.020425] ESI: 4ebd61d5 EDI: f9c80a50 EBP: d568df2c ESP: d568defc
[34839.020433] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[34839.020449] cpuidle_enter+0x14/0x20
[34839.020459] call_cpuidle+0x21/0x40
[34839.020468] do_idle+0xd3/0x1b0
[34839.020478] cpu_startup_entry+0x65/0x70
[34839.020488] rest_init+0x62/0x70
[34839.020501] start_kernel+0x32c/0x342
[34839.020511] i386_start_kernel+0x90/0x94
[34839.020521] startup_32_smp+0x16b/0x16d
[37701.023799] INFO: rcu_sched self-detected stall on CPU
[37701.023830] 0-...: (2 GPs behind) idle=e63/1/0 softirq=5891997/5891997 fqs=0 [37701.023833] INFO: rcu_sched detected stalls on CPUs/tasks:
[37701.023837] (t=58299 jiffies g=3092717 c=3092716 q=0)
[37701.023854] 0-...: (2 GPs behind) idle=e63/1/0 softirq=5891997/5891997 fqs=0 [37701.023857] [37701.023867] rcu_sched kthread starved for 58299 jiffies! g3092717 c3092716 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
[37701.023875] (detected by 1, t=58299 jiffies, g=3092717, c=3092716, q=0)
[37701.023878] rcu_sched S 0 7 2 0x00000000
[37701.023888] Task dump for CPU 0:
[37701.023892] swapper/0 R
[37701.023895] Call Trace:
[37701.023898] running task 0 0 0 0x00000000
[37701.023923] ? __schedule+0x155/0x650
[37701.023935] ? lock_timer_base+0x68/0x80
[37701.023937] Call Trace:
[37701.023951] ? _raw_spin_lock_irqsave+0x14/0x40
[37701.023962] ? cpuidle_enter_state+0x16c/0x350
[37701.023973] schedule+0x2e/0x70
[37701.023981] ? cpuidle_enter+0x14/0x20
[37701.023991] ? call_cpuidle+0x21/0x40
[37701.024000] schedule_timeout+0x18f/0x350
[37701.024009] ? do_idle+0xd3/0x1b0
[37701.024016] ? del_timer_sync+0x60/0x60
[37701.024027] ? cpu_startup_entry+0x65/0x70
[37701.024036] rcu_gp_kthread+0x575/0xce0
[37701.024047] ? rest_init+0x62/0x70
[37701.024055] ? force_qs_rnp+0x170/0x170
[37701.024065] kthread+0xd6/0x110
[37701.024076] ? start_kernel+0x32c/0x342
[37701.024086] ? force_qs_rnp+0x170/0x170
[37701.024094] ? i386_start_kernel+0x90/0x94
[37701.024103] ? startup_32_smp+0x16b/0x16d
[37701.024111] ? kthread_create_on_node+0x30/0x30
[37701.024122] ret_from_fork+0x19/0x24
[37701.024133] rcu_sched kthread starved for 58299 jiffies! g3092717 c3092716 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
[37701.024137] rcu_sched S 0 7 2 0x00000000
[37701.024147] Call Trace:
[37701.024162] ? __schedule+0x155/0x650
[37701.024165] Task dump for CPU 0:
[37701.024169] swapper/0 R
[37701.024178] ? lock_timer_base+0x68/0x80
[37701.024181] running task [37701.024190] ? _raw_spin_lock_irqsave+0x14/0x40
[37701.024197] 0 0 0 0x00000008
[37701.024204] schedule+0x2e/0x70
[37701.024207] Call Trace:
[37701.024216] schedule_timeout+0x18f/0x350
[37701.024221] <IRQ>
[37701.024228] ? del_timer_sync+0x60/0x60
[37701.024239] sched_show_task+0xf3/0x160
[37701.024248] rcu_gp_kthread+0x575/0xce0
[37701.024259] dump_cpu_task+0x37/0x40
[37701.024267] ? force_qs_rnp+0x170/0x170
[37701.024277] kthread+0xd6/0x110
[37701.024287] rcu_dump_cpu_stacks+0x79/0x95
[37701.024297] ? force_qs_rnp+0x170/0x170
[37701.024305] rcu_check_callbacks+0x621/0x770
[37701.024316] ? kthread_create_on_node+0x30/0x30
[37701.024324] update_process_times+0x28/0x50
[37701.024336] tick_sched_handle.isra.11+0x2f/0x40
[37701.024345] ret_from_fork+0x19/0x24
[37701.024356] tick_sched_timer+0x3b/0x80
[37701.024368] __hrtimer_run_queues+0xdb/0x2b0
[37701.024379] ? tick_sched_do_timer+0x60/0x60
[37701.024389] hrtimer_interrupt+0x8b/0x180
[37701.024400] ? default_send_IPI_mask_logical+0x5f/0x80
[37701.024412] tick_handle_oneshot_broadcast+0x14c/0x190
[37701.024425] timer_interrupt+0x12/0x20
[37701.024436] __handle_irq_event_percpu+0x78/0x190
[37701.024448] ? add_interrupt_randomness+0x144/0x1a0
[37701.024459] ? handle_level_irq+0xf0/0xf0
[37701.024469] handle_irq_event_percpu+0x2c/0x70
[37701.024478] handle_irq_event+0x27/0x40
[37701.024488] handle_edge_irq+0x5d/0x120
[37701.024498] handle_irq+0x9b/0xc0
[37701.024502] </IRQ>
[37701.024512] do_IRQ+0x3d/0xc0
[37701.024525] common_interrupt+0x3a/0x40
[37701.024537] EIP: cpuidle_enter_state+0x16c/0x350
[37701.024543] EFLAGS: 00200246 CPU: 0
[37701.024550] EAX: 00000000 EBX: f9c80a40 ECX: 616f6a50 EDX: 00000000
[37701.024558] ESI: 616f6a50 EDI: f9c80a50 EBP: d568df2c ESP: d568defc
[37701.024565] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[37701.024581] cpuidle_enter+0x14/0x20
[37701.024591] call_cpuidle+0x21/0x40
[37701.024600] do_idle+0xd3/0x1b0
[37701.024610] cpu_startup_entry+0x65/0x70
[37701.024620] rest_init+0x62/0x70
[37701.024632] start_kernel+0x32c/0x342
[37701.024643] i386_start_kernel+0x90/0x94
[37701.024652] startup_32_smp+0x16b/0x16d