regression/miss-config ?

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Let me know your thoughts. Thanks in advance !!

[1] https://lkml.org/lkml/2014/12/14/304

Quoted 17 lines · Santosh Shilimkar

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Quoted 2 lines

Let me know your thoughts. Thanks in advance !!

One of my colleague told me the pastebin server I used is Oracle internal only so adding the relevant logs along with email.

Regards,
Santosh

Quoted 2 lines

[1] https://lkml.org/lkml/2014/12/14/304

[2] Log 1 snippet:
-----------------------------------------------------------------

 INFO: rcu_sched self-detected stall on CPU
 INFO: rcu_sched self-detected stall on CPU { 54}  (t=60000 jiffies

g=66023 c=66022 q=0)
Task dump for CPU 54:
ksoftirqd/54 R running task 0 389 2 0x00000008
0000000000000007 ffff88ff7f403d38 ffffffff810a8621 0000000000000036 ffffffff81ab6540 ffff88ff7f403d58 ffffffff810a86cf 0000000000000086 ffffffff81ab6940 ffff88ff7f403d88 ffffffff810e3ad3 ffffffff81ab6540

 Call Trace:
  <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
  [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
  [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
  [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
  [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
  [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
  [<ffffffff810e9772>] update_process_times+0x42/0x70
  [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
  [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
  [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
  [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
  [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
  [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
  [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
  [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
  <EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
  [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0

  [<ffffffff8118e775>] __free_pages+0x25/0x40
  [<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
  [<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
  [<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
  [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
  [<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
  [<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
  [<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]

  [<ffffffff81084b31>] tasklet_action+0xb1/0xc0
  [<ffffffff810854a2>] __do_softirq+0xf2/0x2f0
  [<ffffffff810a4930>] ? smpboot_create_threads+0x80/0x80
  [<ffffffff810856cd>] run_ksoftirqd+0x2d/0x50
  [<ffffffff810a4a46>] smpboot_thread_fn+0x116/0x170
  [<ffffffff810a11ae>] kthread+0xce/0xf0
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff816c1b62>] ret_from_fork+0x42/0x70
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
 Task dump for CPU 66:
 ksoftirqd/66    R  running task        0   474      2 0x00000008
  04208040664afe58 ffff88ff664ac008 000000010005d97a 0000000a39b2e200
  0000000000000018 0000000000000006 ffff88ff664a1c00 ffff88ff669a5260
  ffff88ff664a1c00 ffffffff81aa4ec0 ffffffff810a4930 0000000000000000
 Call Trace:
  [<ffffffff810a4930>] ? smpboot_create_threads+0x80/0x80
  [<ffffffff810856cd>] ? run_ksoftirqd+0x2d/0x50
  [<ffffffff810a4a46>] ? smpboot_thread_fn+0x116/0x170
  [<ffffffff810a11ae>] ? kthread+0xce/0xf0
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff816c1b62>] ? ret_from_fork+0x42/0x70
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
  { 66}  (t=60011 jiffies g=66023 c=66022 q=0)
 Task dump for CPU 54:
 ksoftirqd/54    R  running task        0   389      2 0x00000008
  04208040669e3e58 ffff88ff669e0008 000000010005d981 0000000a39b28e00
  0000000000000000 0000000000000006 ffff88ff669d1c00 ffff88ff669a5020
  ffff88ff669d1c00 ffffffff81aa4ec0 ffffffff810a4930 0000000000000000
 Call Trace:
  [<ffffffff810a4930>] ? smpboot_create_threads+0x80/0x80
  [<ffffffff810856cd>] ? run_ksoftirqd+0x2d/0x50
  [<ffffffff810a4a46>] ? smpboot_thread_fn+0x116/0x170
  [<ffffffff810a11ae>] ? kthread+0xce/0xf0
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff816c1b62>] ? ret_from_fork+0x42/0x70
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
 Task dump for CPU 66:
 ksoftirqd/66    R  running task        0   474      2 0x00000008
  0000000000000003 ffff88ff7f703d38 ffffffff810a8621 0000000000000042
  ffffffff81ab6540 ffff88ff7f703d58 ffffffff810a86cf 0000000000000086
  ffffffff81ab6a40 ffff88ff7f703d88 ffffffff810e3ad3 ffffffff81ab6540
 Call Trace:
  <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
  [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
  [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
  [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
  [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
  [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
  [<ffffffff810e9772>] update_process_times+0x42/0x70
  [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
  [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
  [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
  [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
  [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
  [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
  [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
  [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
  <EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
  [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0
  [<ffffffff8118e775>] __free_pages+0x25/0x40
  [<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
  [<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
  [<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
  [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
  [<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
  [<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
  [<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]
  [<ffffffff81084b31>] tasklet_action+0xb1/0xc0
  [<ffffffff810854a2>] __do_softirq+0xf2/0x2f0
  [<ffffffff810a4930>] ? smpboot_create_threads+0x80/0x80
  [<ffffffff810856cd>] run_ksoftirqd+0x2d/0x50
  [<ffffffff810a4a46>] smpboot_thread_fn+0x116/0x170
  [<ffffffff810a11ae>] kthread+0xce/0xf0
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff816c1b62>] ret_from_fork+0x42/0x70
  [<ffffffff810a10e0>] ? kthread_freezable_should_stop+0x70/0x70
-----------------------------------------------------------------

[3] log 2 snippet
-------------------------------------------------------------------

 INFO: rcu_sched self-detected stall on CPU
 INFO: rcu_sched detected stalls on CPUs/tasks: { 77} (detected by

207, t=60002 jiffies, g=40822, c=40821, q=0)
Task dump for CPU 77:
rds-stress R running task 0 2930 2867 0x0000008a
0000000000000018 0000000000000286 ffff893e00000000 ffffffff810ec828 ffff883f5628d160 0000000000000282 ffff89407ffda440 00000000f4d139b8 0000000100000000 ffff89407ffdae08 0000000000000000 000000004dcc9f40

 Call Trace:
  [<ffffffff810ec828>] ? hrtimer_try_to_cancel+0x48/0xe0
  [<ffffffff8118d7b3>] ? __alloc_pages_nodemask+0x193/0x2b0
  [<ffffffff810c52ac>] ? remove_wait_queue+0x3c/0x50
  [<ffffffff811d747f>] ? alloc_pages_current+0xaf/0x170
  [<ffffffffa2135298>] ? rds_page_remainder_alloc+0x48/0x2a0 [rds]
  [<ffffffffa212f06d>] ? rds_message_copy_from_user+0x6d/0x130 [rds]
  [<ffffffffa2133040>] ? rds_sendmsg+0x470/0x990 [rds]
  [<ffffffff811ffa00>] ? rw_copy_check_uvector+0xa0/0x130
  [<ffffffff815c9ffd>] ? sock_sendmsg+0x4d/0x60
  [<ffffffff815cc93a>] ? ___sys_sendmsg+0x30a/0x330
  [<ffffffff811b77fc>] ? handle_pte_fault+0x20c/0x230
  [<ffffffff815ccb69>] ? __sys_sendmsg+0x49/0x90
  [<ffffffff81023611>] ? syscall_trace_leave+0xf1/0x140
  [<ffffffff815ccbc9>] ? SyS_sendmsg+0x19/0x20
  [<ffffffff816c176e>] ? system_call_fastpath+0x12/0x71
  { 77}  (t=60011 jiffies g=40822 c=40821 q=0)
 Task dump for CPU 77:
 rds-stress      R  running task        0  2930   2867 0x0000008a
  000000000000000e ffff893f7f5439c0 ffffffff810a8621 000000000000004d
  ffffffff81ab6540 ffff893f7f5439e0 ffffffff810a86cf 0000000000000082
  ffffffff81ab6a40 ffff893f7f543a10 ffffffff810e3ad3 ffffffff81ab6540
 Call Trace:
  <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
  [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
  [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
  [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
  [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
  [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
  [<ffffffff810e9772>] update_process_times+0x42/0x70
  [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
  [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
  [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
  [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
  [<ffffffff811df679>] ? __free_slab+0xd9/0x1b0
  [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
  [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
  [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
  [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
  [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0
  [<ffffffff8118e775>] __free_pages+0x25/0x40
  [<ffffffffa212f4f0>] rds_message_purge+0x60/0x150 [rds]
  [<ffffffffa212f624>] rds_message_put+0x44/0x80 [rds]
  [<ffffffffa217d5b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
  [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
  [<ffffffffa18fe273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
  [<ffffffffa21766f1>] poll_cq+0xa1/0xe0 [rds_rdma]
  [<ffffffffa2177489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]
  [<ffffffff81084b31>] tasklet_action+0xb1/0xc0
  [<ffffffff810854a2>] __do_softirq+0xf2/0x2f0
  [<ffffffff810594f4>] ? native_apic_msr_eoi_write+0x14/0x20
  [<ffffffff81085815>] irq_exit+0x125/0x130
  [<ffffffff816c45f5>] do_IRQ+0x65/0x110
  [<ffffffff816c22ae>] common_interrupt+0x6e/0x6e
  <EOI>  [<ffffffff8118bf28>] ? get_page_from_freelist+0x2b8/0x750
  [<ffffffff810ec828>] ? hrtimer_try_to_cancel+0x48/0xe0
  [<ffffffff8118d7b3>] __alloc_pages_nodemask+0x193/0x2b0
  [<ffffffff810c52ac>] ? remove_wait_queue+0x3c/0x50
  [<ffffffff811d747f>] alloc_pages_current+0xaf/0x170
  [<ffffffffa2135298>] rds_page_remainder_alloc+0x48/0x2a0 [rds]
  [<ffffffffa212f06d>] rds_message_copy_from_user+0x6d/0x130 [rds]
  [<ffffffffa2133040>] rds_sendmsg+0x470/0x990 [rds]
  [<ffffffff811ffa00>] ? rw_copy_check_uvector+0xa0/0x130
  [<ffffffff815c9ffd>] sock_sendmsg+0x4d/0x60
  [<ffffffff815cc93a>] ___sys_sendmsg+0x30a/0x330
  [<ffffffff811b77fc>] ? handle_pte_fault+0x20c/0x230
  [<ffffffff815ccb69>] __sys_sendmsg+0x49/0x90
  [<ffffffff81023611>] ? syscall_trace_leave+0xf1/0x140
  [<ffffffff815ccbc9>] SyS_sendmsg+0x19/0x20
  [<ffffffff816c176e>] system_call_fastpath+0x12/0x71
------------------------------------------------------

[5] LOG 3:
------------------------------------------------------

 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=240007 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 240007
(4299336825-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

 Call Trace:
  <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
  [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
  [<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
  [<ffffffff810ee582>] update_process_times+0x42/0x70
  [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
  [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
  [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
  [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
  [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
  [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
  [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
  [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
  [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
  [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
  [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
  [<ffffffff81085bba>] ? __do_softirq+0x18a/0x2d0
  [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
  [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
  [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
  <EOI>
 rcu_sched kthread starved for 240007 jiffies!
 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=420012 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 420012
(4299516830-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffff88010e817800 0000000000017800
ffff88010e8185c0

 Call Trace:
  <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
  [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
  [<ffffffff810ee582>] update_process_times+0x42/0x70
  [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
  [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
  [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
  [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
  [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
  [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
  [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
  [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
  [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
  [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
  [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
  [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
  [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
  [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
  <EOI>  [<ffffffff81024847>] ?
do_audit_syscall_entry+0x67/0x70
  [<ffffffff81025eb3>] syscall_trace_enter_phase1+0x143/0x1a0
  [<ffffffff8112ac86>] ? __audit_syscall_exit+0x1e6/0x280
  [<ffffffff81026216>] ? syscall_trace_leave+0xc6/0x120
  [<ffffffff8170d69a>] tracesys+0xd/0x44
 rcu_sched kthread starved for 420012 jiffies!
 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=600017 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 600017
(4299696835-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

Call Trace:
 <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
 [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
 [<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
 [<ffffffff810ee582>] update_process_times+0x42/0x70
 [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
 [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
 [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
 [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
 [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
 [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
 [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
 [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
 [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
 [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
 [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
 [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
 [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
 [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
 <EOI>

rcu_sched kthread starved for 600017 jiffies!
------------------------------------------------------

[5] RCU config
-----------------------------------------------
# RCU Subsystem
CONFIG_TREE_RCU=y
CONFIG_SRCU=y
# CONFIG_TASKS_RCU is not set
CONFIG_RCU_STALL_COMMON=y
CONFIG_RCU_USER_QS=y
CONFIG_RCU_FANOUT=64
CONFIG_RCU_FANOUT_LEAF=16
# CONFIG_RCU_FANOUT_EXACT is not set
# CONFIG_RCU_FAST_NO_HZ is not set
# CONFIG_TREE_RCU_TRACE is not set
CONFIG_RCU_KTHREAD_PRIO=0
CONFIG_RCU_NOCB_CPU=y
# CONFIG_RCU_NOCB_CPU_NONE is not set
# CONFIG_RCU_NOCB_CPU_ZERO is not set
CONFIG_RCU_NOCB_CPU_ALL=y
# CONFIG_RCU_EXPEDITE_BOOT is not set
# RCU Debugging
# CONFIG_PROVE_RCU is not set
# CONFIG_SPARSE_RCU_POINTER is not set
# CONFIG_RCU_TORTURE_TEST is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
# CONFIG_RCU_CPU_STALL_INFO is not set
# CONFIG_RCU_TRACE is not set
--------------------------------------------------

Quoted 24 lines · On Sun, May 15, 2016 at 09:35:40PM -0700, [email protected] wrote:

Quoted 17 lines · Santosh Shilimkar

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Quoted 2 lines

Let me know your thoughts. Thanks in advance !!

One of my colleague told me the pastebin server I used is Oracle internal only so adding the relevant logs along with email.

Quoted 31 lines

Quoted 1 line

[1] https://lkml.org/lkml/2014/12/14/304

[2] Log 1 snippet:
-----------------------------------------------------------------

 INFO: rcu_sched self-detected stall on CPU
 INFO: rcu_sched self-detected stall on CPU { 54}  (t=60000 jiffies

g=66023 c=66022 q=0)
Task dump for CPU 54:
ksoftirqd/54 R running task 0 389 2 0x00000008
0000000000000007 ffff88ff7f403d38 ffffffff810a8621 0000000000000036 ffffffff81ab6540 ffff88ff7f403d58 ffffffff810a86cf 0000000000000086 ffffffff81ab6940 ffff88ff7f403d88 ffffffff810e3ad3 ffffffff81ab6540

 Call Trace:
  <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
  [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
  [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
  [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
  [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
  [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
  [<ffffffff810e9772>] update_process_times+0x42/0x70
  [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
  [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
  [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
  [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
  [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
  [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
  [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
  [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
  <EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
  [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0

Quoted 8 lines

  [<ffffffff8118e775>] __free_pages+0x25/0x40
  [<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
  [<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
  [<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
  [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
  [<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
  [<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
  [<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]

The most likely possibility is that there is a 60-second-long loop in one of the above functions. This is within bottom-half execution, so unfortunately the usual trick of placing cond_resched_rcu_qs() within this loop, but outside of any RCU read-side critical section does not work.

Therefore, if there really is a loop here, one fix would be to periodically unwind back out to run_ksoftirqd(), but setting up so that the work would be continued later. Another fix might be to move this from tasklet context to workqueue context, where cond_resched_rcu_qs() can be used -- however, this looks a bit like networking code, which does not always take kindly to being run in process context (though careful use of local_bh_disable() and local_bh_enable() can sometimes overcome this issue). A third fix, which works only if this code does not use RCU and does not invoke any code that does use RCU, is to tell RCU that it should ignore this code (which will require a little work on RCU, as it currently does not tolerate this sort of thing aside from the idle threads). In this last approach, event-tracing calls must use the _nonidle suffix.

I am not familiar with the RDS code, so I cannot be more specific.

Quoted 136 lines

[5] LOG 3:
------------------------------------------------------

 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=240007 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 240007
(4299336825-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

 Call Trace:
  <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
  [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
  [<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
  [<ffffffff810ee582>] update_process_times+0x42/0x70
  [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
  [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
  [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
  [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
  [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
  [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
  [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
  [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
  [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
  [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
  [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
  [<ffffffff81085bba>] ? __do_softirq+0x18a/0x2d0
  [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
  [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
  [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
  <EOI>
 rcu_sched kthread starved for 240007 jiffies!
 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=420012 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 420012
(4299516830-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffff88010e817800 0000000000017800
ffff88010e8185c0

 Call Trace:
  <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
  [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
  [<ffffffff810ee582>] update_process_times+0x42/0x70
  [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
  [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
  [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
  [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
  [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
  [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
  [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
  [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
  [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
  [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
  [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
  [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
  [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
  [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
  <EOI>  [<ffffffff81024847>] ?
do_audit_syscall_entry+0x67/0x70
  [<ffffffff81025eb3>] syscall_trace_enter_phase1+0x143/0x1a0
  [<ffffffff8112ac86>] ? __audit_syscall_exit+0x1e6/0x280
  [<ffffffff81026216>] ? syscall_trace_leave+0xc6/0x120
  [<ffffffff8170d69a>] tracesys+0xd/0x44
 rcu_sched kthread starved for 420012 jiffies!
 INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=600017 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 600017
(4299696835-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

Call Trace:
 <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
 [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
 [<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
 [<ffffffff810ee582>] update_process_times+0x42/0x70
 [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
 [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
 [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
 [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
 [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
 [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
 [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
 [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
 [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
 [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
 [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
 [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
 [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
 [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
 <EOI>

rcu_sched kthread starved for 600017 jiffies!
------------------------------------------------------

[5] RCU config
-----------------------------------------------
# RCU Subsystem
CONFIG_TREE_RCU=y
CONFIG_SRCU=y
# CONFIG_TASKS_RCU is not set
CONFIG_RCU_STALL_COMMON=y
CONFIG_RCU_USER_QS=y
CONFIG_RCU_FANOUT=64
CONFIG_RCU_FANOUT_LEAF=16
# CONFIG_RCU_FANOUT_EXACT is not set
# CONFIG_RCU_FAST_NO_HZ is not set
# CONFIG_TREE_RCU_TRACE is not set
CONFIG_RCU_KTHREAD_PRIO=0
CONFIG_RCU_NOCB_CPU=y
# CONFIG_RCU_NOCB_CPU_NONE is not set
# CONFIG_RCU_NOCB_CPU_ZERO is not set
CONFIG_RCU_NOCB_CPU_ALL=y
# CONFIG_RCU_EXPEDITE_BOOT is not set
# RCU Debugging
# CONFIG_PROVE_RCU is not set
# CONFIG_SPARSE_RCU_POINTER is not set
# CONFIG_RCU_TORTURE_TEST is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
# CONFIG_RCU_CPU_STALL_INFO is not set
# CONFIG_RCU_TRACE is not set
--------------------------------------------------

Quoted 25 lines · Paul E. McKenney

Quoted 24 lines · On Sun, May 15, 2016 at 09:35:40PM -0700, [email protected] wrote:

Quoted 17 lines · Santosh Shilimkar

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Quoted 2 lines

Let me know your thoughts. Thanks in advance !!

One of my colleague told me the pastebin server I used is Oracle internal only so adding the relevant logs along with email.

[...]

Quoted 40 lines

Quoted 31 lines

Quoted 1 line

[1] https://lkml.org/lkml/2014/12/14/304

[2] Log 1 snippet:
-----------------------------------------------------------------

INFO: rcu_sched self-detected stall on CPU
INFO: rcu_sched self-detected stall on CPU { 54}  (t=60000 jiffies

g=66023 c=66022 q=0)
Task dump for CPU 54:
ksoftirqd/54 R running task 0 389 2 0x00000008
0000000000000007 ffff88ff7f403d38 ffffffff810a8621 0000000000000036 ffffffff81ab6540 ffff88ff7f403d58 ffffffff810a86cf 0000000000000086 ffffffff81ab6940 ffff88ff7f403d88 ffffffff810e3ad3 ffffffff81ab6540

Call Trace:
 <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
 [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
 [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
 [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
 [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
 [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
 [<ffffffff810e9772>] update_process_times+0x42/0x70
 [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
 [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
 [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
 [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
 [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
 [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
 [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
 [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
 <EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
 [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0

Quoted 8 lines

 [<ffffffff8118e775>] __free_pages+0x25/0x40
 [<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
 [<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
 [<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
 [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
 [<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
 [<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
 [<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]

Quoted 5 lines

The most likely possibility is that there is a 60-second-long loop in one of the above functions. This is within bottom-half execution, so unfortunately the usual trick of placing cond_resched_rcu_qs() within this loop, but outside of any RCU read-side critical section does not work.

First of all thanks for explanation.

There is no loop which can last for 60 seconds in above code since its just completion queue handler used to free up buffers much like NIC
drivers bottom half(NAPI). Its done in tasklet context for latency reasons which RDS care most. Just to get your attention, the RCU stall is also seen with XEN code too. Log for it end of the email.

Another important observation is, for RDS if we avoid higher order page(s) allocation, issue is not reproducible so far. In other words, for PAGE_SIZE(4K, get_order(bytes) ==0) allocations, the system continues to run without any issue, so the loop scenario is ruled out more or less.

To be specific, with PAGE_SIZE allocations, alloc_pages() is just allocating a page and __free_page() is used instead of __free_pages() from below snippet.

------------------
if (bytes >= PAGE_SIZE)

	page = alloc_pages(gfp, get_order(bytes));

.....

(rm->data.op_sg[i].length <= PAGE_SIZE) ?
__free_page(sg_page(&rm->data.op_sg[i])) :
__free_pages(sg_page(&rm->data.op_sg[i]),
get_order(rm->data.op_sg[i].length));
----------------------------

Quoted 14 lines

Therefore, if there really is a loop here, one fix would be to periodically unwind back out to run_ksoftirqd(), but setting up so that the work would be continued later. Another fix might be to move this from tasklet context to workqueue context, where cond_resched_rcu_qs() can be used -- however, this looks a bit like networking code, which does not always take kindly to being run in process context (though careful use of local_bh_disable() and local_bh_enable() can sometimes overcome this issue). A third fix, which works only if this code does not use RCU and does not invoke any code that does use RCU, is to tell RCU that it should ignore this code (which will require a little work on RCU, as it currently does not tolerate this sort of thing aside from the idle threads). In this last approach, event-tracing calls must use the _nonidle suffix.

Quoted 1 line

I am not familiar with the RDS code, so I cannot be more specific.

No worries. Since we saw the issue with XEN too, I was suspecting that somehow we didn't have RCU_TREE config setup correctly or some important RCU patch(s) missing in v4.1 which made it in later kernels.

The only common denominator I saw between these two different usecases (RDS and XEN), was the 'hrtimer_interrupt()' chain which I believe triggers the rcu_sched() chain.

I was thinking of enabling "CONFIG_RCU_TRACE" to see if we can get more information out of the system. Do you suggest any other RCU option(s)/patch(s) which we can help us to capture more information to understand the issue better. I wasn't sure about options like "RCU_KTHREAD_PRIO", TASKS_RCU etc. Used RCU config is also mentioned end of the email.

Regards,
Santosh

Quoted 137 lines

Quoted 136 lines

[5] LOG 3:
------------------------------------------------------

INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=240007 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 240007 (4299336825-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

Call Trace:
 <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
 [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
 [<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
 [<ffffffff810ee582>] update_process_times+0x42/0x70
 [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
 [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
 [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
 [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
 [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
 [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
 [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
 [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
 [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
 [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
 [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
 [<ffffffff81085bba>] ? __do_softirq+0x18a/0x2d0
 [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
 [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
 [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
 <EOI>
rcu_sched kthread starved for 240007 jiffies!
INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=420012 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 420012 (4299516830-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffff88010e817800 0000000000017800
ffff88010e8185c0

Call Trace:
 <IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
 [<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
 [<ffffffff810ee582>] update_process_times+0x42/0x70
 [<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
 [<ffffffff810feae4>] tick_sched_timer+0x44/0x80
 [<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
 [<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
 [<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
 [<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
 [<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
 [<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
 [<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
 [<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
 [<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
 [<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
 [<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
 [<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80
 <EOI>  [<ffffffff81024847>] ?
do_audit_syscall_entry+0x67/0x70
 [<ffffffff81025eb3>] syscall_trace_enter_phase1+0x143/0x1a0
 [<ffffffff8112ac86>] ? __audit_syscall_exit+0x1e6/0x280
 [<ffffffff81026216>] ? syscall_trace_leave+0xc6/0x120
 [<ffffffff8170d69a>] tracesys+0xd/0x44
rcu_sched kthread starved for 420012 jiffies!
INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by

0, t=600017 jiffies, g=449043, c=449042, q=0)
All QSes seen, last rcu_sched kthread activity 600017 (4299696835-4299096818), jiffies_till_next_fqs=3, root ->qsmask 0x0
ora_lms0_orcltw R running task 0 22303 1
0x00000080
ffff8800c4651c00 00000000e7110062 ffff88010e803c18
ffffffff810b038f
ffff88010e8185c0 ffffffff81b22c40 ffff88010e803c98
ffffffff810e8f96
0000000000000000 ffffffff810b4deb ffff88010e817800
ffff88010e8185c0

Call Trace:
<IRQ>  [<ffffffff810b038f>] sched_show_task+0xaf/0x120
[<ffffffff810e8f96>] rcu_check_callbacks+0x7e6/0x7f0
[<ffffffff810b4deb>] ? account_user_time+0x8b/0xa0
[<ffffffff810ee582>] update_process_times+0x42/0x70
[<ffffffff810fea65>] tick_sched_handle.isra.18+0x25/0x60
[<ffffffff810feae4>] tick_sched_timer+0x44/0x80
[<ffffffff810ef307>] __run_hrtimer+0x77/0x1d0
[<ffffffff810feaa0>] ? tick_sched_handle.isra.18+0x60/0x60
[<ffffffff810ef6e3>] hrtimer_interrupt+0x103/0x230
[<ffffffff8100a64d>] xen_timer_interrupt+0x3d/0x170
[<ffffffff814469a9>] ? add_interrupt_randomness+0x49/0x200
[<ffffffff810dd1ae>] handle_irq_event_percpu+0x3e/0x1a0
[<ffffffff810e0cfd>] handle_percpu_irq+0x3d/0x60
[<ffffffff810dc7ab>] generic_handle_irq+0x2b/0x40
[<ffffffff813fe91f>] evtchn_2l_handle_events+0x26f/0x280
[<ffffffff813fbe8f>] __xen_evtchn_do_upcall+0x4f/0x90
[<ffffffff813fddf4>] xen_evtchn_do_upcall+0x34/0x50
[<ffffffff8170f35e>] xen_hvm_callback_vector+0x6e/0x80

<EOI>
rcu_sched kthread starved for 600017 jiffies!
------------------------------------------------------

[5] RCU config
-----------------------------------------------
# RCU Subsystem
CONFIG_TREE_RCU=y
CONFIG_SRCU=y
# CONFIG_TASKS_RCU is not set
CONFIG_RCU_STALL_COMMON=y
CONFIG_RCU_USER_QS=y
CONFIG_RCU_FANOUT=64
CONFIG_RCU_FANOUT_LEAF=16
# CONFIG_RCU_FANOUT_EXACT is not set
# CONFIG_RCU_FAST_NO_HZ is not set
# CONFIG_TREE_RCU_TRACE is not set
CONFIG_RCU_KTHREAD_PRIO=0
CONFIG_RCU_NOCB_CPU=y
# CONFIG_RCU_NOCB_CPU_NONE is not set
# CONFIG_RCU_NOCB_CPU_ZERO is not set
CONFIG_RCU_NOCB_CPU_ALL=y
# CONFIG_RCU_EXPEDITE_BOOT is not set
# RCU Debugging
# CONFIG_PROVE_RCU is not set
# CONFIG_SPARSE_RCU_POINTER is not set
# CONFIG_RCU_TORTURE_TEST is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
# CONFIG_RCU_CPU_STALL_INFO is not set
# CONFIG_RCU_TRACE is not set
--------------------------------------------------

Quoted 99 lines · Santosh Shilimkar

Quoted 25 lines · Paul E. McKenney

Quoted 24 lines · On Sun, May 15, 2016 at 09:35:40PM -0700, [email protected] wrote:

Quoted 17 lines · Santosh Shilimkar

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Quoted 2 lines

Let me know your thoughts. Thanks in advance !!

One of my colleague told me the pastebin server I used is Oracle internal only so adding the relevant logs along with email.

[...]

Quoted 40 lines

Quoted 31 lines

Quoted 1 line

[1] https://lkml.org/lkml/2014/12/14/304

[2] Log 1 snippet:
-----------------------------------------------------------------

INFO: rcu_sched self-detected stall on CPU
INFO: rcu_sched self-detected stall on CPU { 54}  (t=60000 jiffies

g=66023 c=66022 q=0)
Task dump for CPU 54:
ksoftirqd/54 R running task 0 389 2 0x00000008
0000000000000007 ffff88ff7f403d38 ffffffff810a8621 0000000000000036 ffffffff81ab6540 ffff88ff7f403d58 ffffffff810a86cf 0000000000000086 ffffffff81ab6940 ffff88ff7f403d88 ffffffff810e3ad3 ffffffff81ab6540

Call Trace:
 <IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
 [<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
 [<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
 [<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
 [<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
 [<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
 [<ffffffff810e9772>] update_process_times+0x42/0x70
 [<ffffffff810fb589>] tick_sched_handle+0x39/0x80
 [<ffffffff810fb824>] tick_sched_timer+0x44/0x80
 [<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
 [<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
 [<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
 [<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
 [<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
 [<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
 <EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
 [<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0

Quoted 8 lines

 [<ffffffff8118e775>] __free_pages+0x25/0x40
 [<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
 [<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
 [<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
 [<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
 [<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
 [<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
 [<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]

Quoted 5 lines

The most likely possibility is that there is a 60-second-long loop in one of the above functions. This is within bottom-half execution, so unfortunately the usual trick of placing cond_resched_rcu_qs() within this loop, but outside of any RCU read-side critical section does not work.

First of all thanks for explanation.

There is no loop which can last for 60 seconds in above code since its just completion queue handler used to free up buffers much like NIC
drivers bottom half(NAPI). Its done in tasklet context for latency reasons which RDS care most. Just to get your attention, the RCU stall is also seen with XEN code too. Log for it end of the email.

Another important observation is, for RDS if we avoid higher order page(s) allocation, issue is not reproducible so far. In other words, for PAGE_SIZE(4K, get_order(bytes) ==0) allocations, the system continues to run without any issue, so the loop scenario is ruled out more or less.

To be specific, with PAGE_SIZE allocations, alloc_pages() is just allocating a page and __free_page() is used instead of __free_pages() from below snippet.

------------------
if (bytes >= PAGE_SIZE)

	page = alloc_pages(gfp, get_order(bytes));

.....

Quoted 5 lines

(rm->data.op_sg[i].length <= PAGE_SIZE) ?
__free_page(sg_page(&rm->data.op_sg[i])) :
__free_pages(sg_page(&rm->data.op_sg[i]),
get_order(rm->data.op_sg[i].length));
----------------------------

This sounds like something to take up with the mm folks.

Quoted 16 lines

Quoted 14 lines

Therefore, if there really is a loop here, one fix would be to periodically unwind back out to run_ksoftirqd(), but setting up so that the work would be continued later. Another fix might be to move this from tasklet context to workqueue context, where cond_resched_rcu_qs() can be used -- however, this looks a bit like networking code, which does not always take kindly to being run in process context (though careful use of local_bh_disable() and local_bh_enable() can sometimes overcome this issue). A third fix, which works only if this code does not use RCU and does not invoke any code that does use RCU, is to tell RCU that it should ignore this code (which will require a little work on RCU, as it currently does not tolerate this sort of thing aside from the idle threads). In this last approach, event-tracing calls must use the _nonidle suffix.

Quoted 1 line

I am not familiar with the RDS code, so I cannot be more specific.

Quoted 8 lines

No worries. Since we saw the issue with XEN too, I was suspecting that somehow we didn't have RCU_TREE config setup correctly or some important RCU patch(s) missing in v4.1 which made it in later kernels.

The only common denominator I saw between these two different usecases (RDS and XEN), was the 'hrtimer_interrupt()' chain which I believe triggers the rcu_sched() chain.

Exactly!

Quoted 6 lines

I was thinking of enabling "CONFIG_RCU_TRACE" to see if we can get more information out of the system. Do you suggest any other RCU option(s)/patch(s) which we can help us to capture more information to understand the issue better. I wasn't sure about options like "RCU_KTHREAD_PRIO", TASKS_RCU etc. Used RCU config is also mentioned end of the email.

Hmmm... I just now noticed the "All QSes seen" message below. That can happen if the load is quite high, and could as you say one thing to try would be to set CONFIG_RCU_KTHREAD_PRIO=1. This is not free, as it will mean more context switches involving the RCU grace-period kthreads.

Another thing to try is to set CONFIG_RCU_CPU_STALL_TIMEOUT to something smaller than 60, say, 21. This will cause the stall warnings to leave less time before splatting.

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Quoted 106 lines · Paul E. McKenney

Quoted 104 lines · Santosh Shilimkar

Quoted 25 lines · Paul E. McKenney

Quoted 24 lines · On Sun, May 15, 2016 at 09:35:40PM -0700, [email protected] wrote:

Quoted 17 lines · Santosh Shilimkar

Hi Paul,

I was asking Sasha about [1] since other folks in Oracle also stumbled upon similar RCU stalls with v4.1 kernel in different workloads. I was reported similar issue with RDS as well and looking at [1], [2], [3] and [4], thought of reaching out to see if you can help us to understand this issue better.

Have also included RCU specific config used in these test(s). Its very hard to reproduce the issue but one of the data point is, it reproduces on systems with larger CPUs(64+). Same workload with less than 64 CPUs, don't show the issue. Someone also told me, making use of SLAB instead SLUB allocator makes difference but I haven't verified that part for RDS.

Quoted 2 lines

Let me know your thoughts. Thanks in advance !!

One of my colleague told me the pastebin server I used is Oracle internal only so adding the relevant logs along with email.

[...]

Quoted 40 lines

Quoted 31 lines

Quoted 1 line

[1] https://lkml.org/lkml/2014/12/14/304

[2] Log 1 snippet:
-----------------------------------------------------------------

INFO: rcu_sched self-detected stall on CPU
INFO: rcu_sched self-detected stall on CPU { 54}  (t=60000 jiffies

g=66023 c=66022 q=0)
Task dump for CPU 54:
ksoftirqd/54 R running task 0 389 2 0x00000008
0000000000000007 ffff88ff7f403d38 ffffffff810a8621 0000000000000036 ffffffff81ab6540 ffff88ff7f403d58 ffffffff810a86cf 0000000000000086 ffffffff81ab6940 ffff88ff7f403d88 ffffffff810e3ad3 ffffffff81ab6540

Call Trace:
<IRQ>  [<ffffffff810a8621>] sched_show_task+0xb1/0x120
[<ffffffff810a86cf>] dump_cpu_task+0x3f/0x50
[<ffffffff810e3ad3>] rcu_dump_cpu_stacks+0x83/0xc0
[<ffffffff810e490c>] print_cpu_stall+0xfc/0x170
[<ffffffff810e5eeb>] __rcu_pending+0x2bb/0x2c0
[<ffffffff810e5f8d>] rcu_check_callbacks+0x9d/0x170
[<ffffffff810e9772>] update_process_times+0x42/0x70
[<ffffffff810fb589>] tick_sched_handle+0x39/0x80
[<ffffffff810fb824>] tick_sched_timer+0x44/0x80
[<ffffffff810ebc04>] __run_hrtimer+0x74/0x1d0
[<ffffffff810fb7e0>] ? tick_nohz_handler+0xa0/0xa0
[<ffffffff810ebf92>] hrtimer_interrupt+0x102/0x240
[<ffffffff810521f9>] local_apic_timer_interrupt+0x39/0x60
[<ffffffff816c47b5>] smp_apic_timer_interrupt+0x45/0x59
[<ffffffff816c263e>] apic_timer_interrupt+0x6e/0x80
<EOI>  [<ffffffff8118db64>] ? free_one_page+0x164/0x380
[<ffffffff8118de43>] ? __free_pages_ok+0xc3/0xe0

Quoted 8 lines

[<ffffffff8118e775>] __free_pages+0x25/0x40
[<ffffffffa21054f0>] rds_message_purge+0x60/0x150 [rds]
[<ffffffffa2105624>] rds_message_put+0x44/0x80 [rds]
[<ffffffffa21535b4>] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma]
[<ffffffff816c102b>] ? _raw_spin_unlock_irqrestore+0x1b/0x50
[<ffffffffa18c0273>] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib]
[<ffffffffa214c6f1>] poll_cq+0xa1/0xe0 [rds_rdma]
[<ffffffffa214d489>] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma]

Quoted 5 lines

The most likely possibility is that there is a 60-second-long loop in one of the above functions. This is within bottom-half execution, so unfortunately the usual trick of placing cond_resched_rcu_qs() within this loop, but outside of any RCU read-side critical section does not work.

First of all thanks for explanation.

There is no loop which can last for 60 seconds in above code since its just completion queue handler used to free up buffers much like NIC
drivers bottom half(NAPI). Its done in tasklet context for latency reasons which RDS care most. Just to get your attention, the RCU stall is also seen with XEN code too. Log for it end of the email.

Another important observation is, for RDS if we avoid higher order page(s) allocation, issue is not reproducible so far. In other words, for PAGE_SIZE(4K, get_order(bytes) ==0) allocations, the system continues to run without any issue, so the loop scenario is ruled out more or less.

To be specific, with PAGE_SIZE allocations, alloc_pages() is just allocating a page and __free_page() is used instead of __free_pages() from below snippet.

------------------
if (bytes >= PAGE_SIZE)

	page = alloc_pages(gfp, get_order(bytes));

.....

(rm->data.op_sg[i].length <= PAGE_SIZE) ?
__free_page(sg_page(&rm->data.op_sg[i])) :
__free_pages(sg_page(&rm->data.op_sg[i]),
get_order(rm->data.op_sg[i].length));
----------------------------

Quoted 2 lines

This sounds like something to take up with the mm folks.

Sure. Will do once the link between two issues is established.

Quoted 40 lines

Quoted 16 lines

Quoted 14 lines

Therefore, if there really is a loop here, one fix would be to periodically unwind back out to run_ksoftirqd(), but setting up so that the work would be continued later. Another fix might be to move this from tasklet context to workqueue context, where cond_resched_rcu_qs() can be used -- however, this looks a bit like networking code, which does not always take kindly to being run in process context (though careful use of local_bh_disable() and local_bh_enable() can sometimes overcome this issue). A third fix, which works only if this code does not use RCU and does not invoke any code that does use RCU, is to tell RCU that it should ignore this code (which will require a little work on RCU, as it currently does not tolerate this sort of thing aside from the idle threads). In this last approach, event-tracing calls must use the _nonidle suffix.

Quoted 1 line

I am not familiar with the RDS code, so I cannot be more specific.

Quoted 8 lines

No worries. Since we saw the issue with XEN too, I was suspecting that somehow we didn't have RCU_TREE config setup correctly or some important RCU patch(s) missing in v4.1 which made it in later kernels.

The only common denominator I saw between these two different usecases (RDS and XEN), was the 'hrtimer_interrupt()' chain which I believe triggers the rcu_sched() chain.

Exactly!

Quoted 6 lines

I was thinking of enabling "CONFIG_RCU_TRACE" to see if we can get more information out of the system. Do you suggest any other RCU option(s)/patch(s) which we can help us to capture more information to understand the issue better. I wasn't sure about options like "RCU_KTHREAD_PRIO", TASKS_RCU etc. Used RCU config is also mentioned end of the email.

Hmmm... I just now noticed the "All QSes seen" message below. That can happen if the load is quite high, and could as you say one thing to try would be to set CONFIG_RCU_KTHREAD_PRIO=1. This is not free, as it will mean more context switches involving the RCU grace-period kthreads.

Quoted 4 lines

Another thing to try is to set CONFIG_RCU_CPU_STALL_TIMEOUT to something smaller than 60, say, 21. This will cause the stall warnings to leave less time before splatting.

OK will try with CONFIG_RCU_KTHREAD_PRIO=1 & CONFIG_RCU_CPU_STALL_TIMEOUT =21 . Indeed the usecases generate very high load on the systems.

Quoted 3 lines

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Yes, CONFIG_NO_HZ_FULL=y. Do you mean "CONFIG_NO_HZ_FULL_ALL=y" for book keeping. Seems like without that clock-event code will just use CPU0 for things like broadcasting which might become bottleneck. This could explain connect the hrtimer_interrupt() path getting slowed down because of book keeping bottleneck.

$cat .config | grep NO_HZ
CONFIG_NO_HZ_COMMON=y
# CONFIG_NO_HZ_IDLE is not set
CONFIG_NO_HZ_FULL=y
# CONFIG_NO_HZ_FULL_ALL is not set
# CONFIG_NO_HZ_FULL_SYSIDLE is not set
CONFIG_NO_HZ=y
# CONFIG_RCU_FAST_NO_HZ is not set

Quoted 2 lines · Santosh Shilimkar

Quoted 1 line · Paul E. McKenney

On Mon, May 16, 2016 at 09:33:57AM -0700, Santosh Shilimkar wrote:

Quoted 9 lines

Quoted 3 lines

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Yes, CONFIG_NO_HZ_FULL=y. Do you mean "CONFIG_NO_HZ_FULL_ALL=y" for book keeping. Seems like without that clock-event code will just use CPU0 for things like broadcasting which might become bottleneck. This could explain connect the hrtimer_interrupt() path getting slowed down because of book keeping bottleneck.

Quoted 8 lines

$cat .config | grep NO_HZ
CONFIG_NO_HZ_COMMON=y
# CONFIG_NO_HZ_IDLE is not set
CONFIG_NO_HZ_FULL=y
# CONFIG_NO_HZ_FULL_ALL is not set
# CONFIG_NO_HZ_FULL_SYSIDLE is not set
CONFIG_NO_HZ=y
# CONFIG_RCU_FAST_NO_HZ is not set

Yes, CONFIG_NO_HZ_FULL_ALL=y would give you only one CPU for all housekeeping tasks, including the RCU grace-period kthreads. So you are booting without any nohz_full boot parameter? You can end up with the same problem with CONFIG_NO_HZ_FULL=y and the nohz_full boot parameter that you can with CONFIG_NO_HZ_FULL_ALL=y.

Quoted 3 lines · Paul E. McKenney

Quoted 2 lines · Santosh Shilimkar

Quoted 1 line · Paul E. McKenney

On Mon, May 16, 2016 at 09:33:57AM -0700, Santosh Shilimkar wrote:

[...]

Quoted 18 lines

Quoted 9 lines

Quoted 3 lines

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Yes, CONFIG_NO_HZ_FULL=y. Do you mean "CONFIG_NO_HZ_FULL_ALL=y" for book keeping. Seems like without that clock-event code will just use CPU0 for things like broadcasting which might become bottleneck. This could explain connect the hrtimer_interrupt() path getting slowed down because of book keeping bottleneck.

Quoted 8 lines

$cat .config | grep NO_HZ
CONFIG_NO_HZ_COMMON=y
# CONFIG_NO_HZ_IDLE is not set
CONFIG_NO_HZ_FULL=y
# CONFIG_NO_HZ_FULL_ALL is not set
# CONFIG_NO_HZ_FULL_SYSIDLE is not set
CONFIG_NO_HZ=y
# CONFIG_RCU_FAST_NO_HZ is not set

Quoted 6 lines

Yes, CONFIG_NO_HZ_FULL_ALL=y would give you only one CPU for all housekeeping tasks, including the RCU grace-period kthreads. So you are booting without any nohz_full boot parameter? You can end up with the same problem with CONFIG_NO_HZ_FULL=y and the nohz_full boot parameter that you can with CONFIG_NO_HZ_FULL_ALL=y.

I see. Yes, the systems are booting without nohz_full boot parameter. Will try to add more CPUs to it & update the thread
after the verification since it takes time to reproduce the issue.

Thanks for discussion so far Paul. Its very insightful for me.

Quoted 31 lines · On Tue, May 17, 2016 at 06:46:22AM -0700, [email protected] wrote:

Quoted 3 lines · Paul E. McKenney

Quoted 2 lines · Santosh Shilimkar

Quoted 1 line · Paul E. McKenney

On Mon, May 16, 2016 at 09:33:57AM -0700, Santosh Shilimkar wrote:

[...]

Quoted 24 lines

Quoted 9 lines

Quoted 3 lines

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Yes, CONFIG_NO_HZ_FULL=y. Do you mean "CONFIG_NO_HZ_FULL_ALL=y" for book keeping. Seems like without that clock-event code will just use CPU0 for things like broadcasting which might become bottleneck. This could explain connect the hrtimer_interrupt() path getting slowed down because of book keeping bottleneck.

Quoted 8 lines

$cat .config | grep NO_HZ
CONFIG_NO_HZ_COMMON=y
# CONFIG_NO_HZ_IDLE is not set
CONFIG_NO_HZ_FULL=y
# CONFIG_NO_HZ_FULL_ALL is not set
# CONFIG_NO_HZ_FULL_SYSIDLE is not set
CONFIG_NO_HZ=y
# CONFIG_RCU_FAST_NO_HZ is not set

Yes, CONFIG_NO_HZ_FULL_ALL=y would give you only one CPU for all housekeeping tasks, including the RCU grace-period kthreads. So you are booting without any nohz_full boot parameter? You can end up with the same problem with CONFIG_NO_HZ_FULL=y and the nohz_full boot parameter that you can with CONFIG_NO_HZ_FULL_ALL=y.

Quoted 5 lines

I see. Yes, the systems are booting without nohz_full boot parameter. Will try to add more CPUs to it & update the thread
after the verification since it takes time to reproduce the issue.

Thanks for discussion so far Paul. Its very insightful for me.

Please let me know how things go with further testing, especially with the priority setting.

Hi Paul,

Quoted 32 lines · Paul E. McKenney

Quoted 31 lines · On Tue, May 17, 2016 at 06:46:22AM -0700, [email protected] wrote:

Quoted 3 lines · Paul E. McKenney

Quoted 2 lines · Santosh Shilimkar

Quoted 1 line · Paul E. McKenney

On Mon, May 16, 2016 at 09:33:57AM -0700, Santosh Shilimkar wrote:

[...]

Quoted 24 lines

Quoted 9 lines

Quoted 3 lines

Are you running CONFIG_NO_HZ_FULL=y? If so, the problem might be that you need more housekeeping CPUs than you currently have configured.

Yes, CONFIG_NO_HZ_FULL=y. Do you mean "CONFIG_NO_HZ_FULL_ALL=y" for book keeping. Seems like without that clock-event code will just use CPU0 for things like broadcasting which might become bottleneck. This could explain connect the hrtimer_interrupt() path getting slowed down because of book keeping bottleneck.

Quoted 8 lines

$cat .config | grep NO_HZ
CONFIG_NO_HZ_COMMON=y
# CONFIG_NO_HZ_IDLE is not set
CONFIG_NO_HZ_FULL=y
# CONFIG_NO_HZ_FULL_ALL is not set
# CONFIG_NO_HZ_FULL_SYSIDLE is not set
CONFIG_NO_HZ=y
# CONFIG_RCU_FAST_NO_HZ is not set

Yes, CONFIG_NO_HZ_FULL_ALL=y would give you only one CPU for all housekeeping tasks, including the RCU grace-period kthreads. So you are booting without any nohz_full boot parameter? You can end up with the same problem with CONFIG_NO_HZ_FULL=y and the nohz_full boot parameter that you can with CONFIG_NO_HZ_FULL_ALL=y.

Quoted 9 lines

Quoted 5 lines

I see. Yes, the systems are booting without nohz_full boot parameter. Will try to add more CPUs to it & update the thread
after the verification since it takes time to reproduce the issue.

Thanks for discussion so far Paul. Its very insightful for me.

Please let me know how things go with further testing, especially with the priority setting.

Sorry for delay. I manage to get information about XEN usecase custom config as discussed above. To reduce variables, I disabled "CONFIG_NO_HZ_FULL" altogether. So the effective setting was:

CONFIG_NO_HZ_IDLE=y
# CONFIG_NO_HZ_FULL is not set
CONFIG_TREE_RCU_TRACE=y
CONFIG_RCU_KTHREAD_PRIO=1
CONFIG_RCU_CPU_STALL_TIMEOUT=21
CONFIG_RCU_TRACE=y

Unfortunately the XEN test still failed. Log end of the email. This test(s) is bit peculiar though since its database running in VM with 1 or 2 CPUs. One of the suspect is because the database RT processes are hogging the CPU(s), kernel RCU thread is not getting chance to run which eventually results in stall. Does it make sense ?

Please note that its non-preempt kernel using RT processes. ;-)

# cat .config | grep PREEMPT
CONFIG_PREEMPT_NOTIFIERS=y
# CONFIG_PREEMPT_NONE is not set
CONFIG_PREEMPT_VOLUNTARY=y
# CONFIG_PREEMPT is not set

Regards,
Santosh
...
....
rcu_sched kthread starved for 399032 jiffies!

INFO: rcu_sched detected stalls on CPUs/tasks: {} (detected by 0,

t=462037 jiffies, g=118888, c=118887, q=0)
All QSes seen, last rcu_sched kthread activity 462037 (4296277632-4295815595), jiffies_till_next_fqs=3, root ->qsmask 0x0
ocssd.bin R running task 0 15375 1 0x00000000
0000000000000000 ffff8800ec003bc8 ffffffff810a8581 ffffffff81abf980 000000000001d068 ffff8800ec003c28 ffffffff810e9c98 0000000000000000 0000000000000086 0000000000000000 0000000000000086 0000000000000082

Call Trace:
 <IRQ>  [<ffffffff810a8581>] sched_show_task+0xb1/0x120
 [<ffffffff810e9c98>] print_other_cpu_stall+0x288/0x2d0
 [<ffffffff810e9e60>] __rcu_pending+0x180/0x230
 [<ffffffff810e9fa5>] rcu_check_callbacks+0x95/0x140
 [<ffffffff810edf92>] update_process_times+0x42/0x70
 [<ffffffff810ffc79>] tick_sched_handle+0x39/0x80
 [<ffffffff810ffee2>] tick_sched_timer+0x52/0xa0
 [<ffffffff810f0424>] __run_hrtimer+0x74/0x1d0
 [<ffffffff810ffe90>] ? tick_nohz_handler+0xc0/0xc0
 [<ffffffff810f07b2>] hrtimer_interrupt+0x102/0x240
 [<ffffffff8100aaae>] xen_timer_interrupt+0x2e/0x130
 [<ffffffff8143347a>] ? add_interrupt_randomness+0x3a/0x1f0
 [<ffffffff81384290>] ? store_cursor_blink+0xc0/0xc0
 [<ffffffff810d9de4>] handle_irq_event_percpu+0x54/0x1b0
 [<ffffffff810dd477>] handle_percpu_irq+0x47/0x70
 [<ffffffff810d9d27>] generic_handle_irq+0x27/0x40
 [<ffffffff813e53ca>] evtchn_2l_handle_events+0x25a/0x260
 [<ffffffff81085541>] ? __do_softirq+0x191/0x2f0
 [<ffffffff813e2c2f>] __xen_evtchn_do_upcall+0x4f/0x90
 [<ffffffff813e3404>] xen_evtchn_do_upcall+0x34/0x50
 [<ffffffff816c761e>] xen_hvm_callback_vector+0x6e/0x80
 <EOI>

rcu_sched kthread starved for 462037 jiffies!