linux-kernel - Re: INFO: rcu_sched self-detected stall on CPU

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] [day] [month] [year] [list]
Date:   Thu, 5 Jan 2017 23:48:28 -0800
From:   "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>
To:     Enrico Mioso <mrkiko.rs@...il.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

On Thu, Jan 05, 2017 at 07:32:45PM +0100, Enrico Mioso wrote:
> Here is a new trace in the meanwhile: reporting it in case it proves useful.
> Thank you very much for your help and patience.

This looks quite similar to the last one.  So there appears to be some
consistency, which is reassuring.  Maybe fewer rather than more bugs in
play here.

							Thanx, Paul

> 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
>