Date:   Thu, 5 Jan 2017 19:32:45 +0100 (CET)
From:   Enrico Mioso <mrkiko.rs@...il.com>
To:     "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>
cc:     Steven Rostedt <rostedt@...dmis.org>, linux-kernel@...r.kernel.org,
        Josh Triplett <josh@...htriplett.org>,
        Mathieu Desnoyers <mathieu.desnoyers@...icios.com>
Subject: Re: INFO: rcu_sched self-detected stall on CPU

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

Powered by blists - more mailing lists