From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751191AbcEPEf4 (ORCPT ); Mon, 16 May 2016 00:35:56 -0400 Received: from userp1040.oracle.com ([156.151.31.81]:25989 "EHLO userp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750721AbcEPEfy (ORCPT ); Mon, 16 May 2016 00:35:54 -0400 From: "santosh.shilimkar@oracle.com" Subject: Re: [rcu_sched stall] regression/miss-config ? To: paulmck@linux.vnet.ibm.com, linux-kernel@vger.kernel.org References: Cc: Sasha Levin Organization: Oracle Corporation Message-ID: Date: Sun, 15 May 2016 21:35:40 -0700 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:45.0) Gecko/20100101 Thunderbird/45.0 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit X-Source-IP: userv0021.oracle.com [156.151.31.71] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 5/15/16 2:18 PM, Santosh Shilimkar wrote: > 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 !! > 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 > > [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: [] sched_show_task+0xb1/0x120 [] dump_cpu_task+0x3f/0x50 [] rcu_dump_cpu_stacks+0x83/0xc0 [] print_cpu_stall+0xfc/0x170 [] __rcu_pending+0x2bb/0x2c0 [] rcu_check_callbacks+0x9d/0x170 [] update_process_times+0x42/0x70 [] tick_sched_handle+0x39/0x80 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x74/0x1d0 [] ? tick_nohz_handler+0xa0/0xa0 [] hrtimer_interrupt+0x102/0x240 [] local_apic_timer_interrupt+0x39/0x60 [] smp_apic_timer_interrupt+0x45/0x59 [] apic_timer_interrupt+0x6e/0x80 [] ? free_one_page+0x164/0x380 [] ? __free_pages_ok+0xc3/0xe0 [] __free_pages+0x25/0x40 [] rds_message_purge+0x60/0x150 [rds] [] rds_message_put+0x44/0x80 [rds] [] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma] [] ? _raw_spin_unlock_irqrestore+0x1b/0x50 [] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib] [] poll_cq+0xa1/0xe0 [rds_rdma] [] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma] [] tasklet_action+0xb1/0xc0 [] __do_softirq+0xf2/0x2f0 [] ? smpboot_create_threads+0x80/0x80 [] run_ksoftirqd+0x2d/0x50 [] smpboot_thread_fn+0x116/0x170 [] kthread+0xce/0xf0 [] ? kthread_freezable_should_stop+0x70/0x70 [] ret_from_fork+0x42/0x70 [] ? 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: [] ? smpboot_create_threads+0x80/0x80 [] ? run_ksoftirqd+0x2d/0x50 [] ? smpboot_thread_fn+0x116/0x170 [] ? kthread+0xce/0xf0 [] ? kthread_freezable_should_stop+0x70/0x70 [] ? ret_from_fork+0x42/0x70 [] ? 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: [] ? smpboot_create_threads+0x80/0x80 [] ? run_ksoftirqd+0x2d/0x50 [] ? smpboot_thread_fn+0x116/0x170 [] ? kthread+0xce/0xf0 [] ? kthread_freezable_should_stop+0x70/0x70 [] ? ret_from_fork+0x42/0x70 [] ? 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: [] sched_show_task+0xb1/0x120 [] dump_cpu_task+0x3f/0x50 [] rcu_dump_cpu_stacks+0x83/0xc0 [] print_cpu_stall+0xfc/0x170 [] __rcu_pending+0x2bb/0x2c0 [] rcu_check_callbacks+0x9d/0x170 [] update_process_times+0x42/0x70 [] tick_sched_handle+0x39/0x80 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x74/0x1d0 [] ? tick_nohz_handler+0xa0/0xa0 [] hrtimer_interrupt+0x102/0x240 [] local_apic_timer_interrupt+0x39/0x60 [] smp_apic_timer_interrupt+0x45/0x59 [] apic_timer_interrupt+0x6e/0x80 [] ? free_one_page+0x164/0x380 [] ? __free_pages_ok+0xc3/0xe0 [] __free_pages+0x25/0x40 [] rds_message_purge+0x60/0x150 [rds] [] rds_message_put+0x44/0x80 [rds] [] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma] [] ? _raw_spin_unlock_irqrestore+0x1b/0x50 [] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib] [] poll_cq+0xa1/0xe0 [rds_rdma] [] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma] [] tasklet_action+0xb1/0xc0 [] __do_softirq+0xf2/0x2f0 [] ? smpboot_create_threads+0x80/0x80 [] run_ksoftirqd+0x2d/0x50 [] smpboot_thread_fn+0x116/0x170 [] kthread+0xce/0xf0 [] ? kthread_freezable_should_stop+0x70/0x70 [] ret_from_fork+0x42/0x70 [] ? 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: [] ? hrtimer_try_to_cancel+0x48/0xe0 [] ? __alloc_pages_nodemask+0x193/0x2b0 [] ? remove_wait_queue+0x3c/0x50 [] ? alloc_pages_current+0xaf/0x170 [] ? rds_page_remainder_alloc+0x48/0x2a0 [rds] [] ? rds_message_copy_from_user+0x6d/0x130 [rds] [] ? rds_sendmsg+0x470/0x990 [rds] [] ? rw_copy_check_uvector+0xa0/0x130 [] ? sock_sendmsg+0x4d/0x60 [] ? ___sys_sendmsg+0x30a/0x330 [] ? handle_pte_fault+0x20c/0x230 [] ? __sys_sendmsg+0x49/0x90 [] ? syscall_trace_leave+0xf1/0x140 [] ? SyS_sendmsg+0x19/0x20 [] ? 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: [] sched_show_task+0xb1/0x120 [] dump_cpu_task+0x3f/0x50 [] rcu_dump_cpu_stacks+0x83/0xc0 [] print_cpu_stall+0xfc/0x170 [] __rcu_pending+0x2bb/0x2c0 [] rcu_check_callbacks+0x9d/0x170 [] update_process_times+0x42/0x70 [] tick_sched_handle+0x39/0x80 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x74/0x1d0 [] ? tick_nohz_handler+0xa0/0xa0 [] ? __free_slab+0xd9/0x1b0 [] hrtimer_interrupt+0x102/0x240 [] local_apic_timer_interrupt+0x39/0x60 [] smp_apic_timer_interrupt+0x45/0x59 [] apic_timer_interrupt+0x6e/0x80 [] ? free_one_page+0x164/0x380 [] ? __free_pages_ok+0xc3/0xe0 [] __free_pages+0x25/0x40 [] rds_message_purge+0x60/0x150 [rds] [] rds_message_put+0x44/0x80 [rds] [] rds_ib_send_cqe_handler+0x134/0x2d0 [rds_rdma] [] ? _raw_spin_unlock_irqrestore+0x1b/0x50 [] ? mlx4_ib_poll_cq+0xb3/0x2a0 [mlx4_ib] [] poll_cq+0xa1/0xe0 [rds_rdma] [] rds_ib_tasklet_fn_send+0x79/0xf0 [rds_rdma] [] tasklet_action+0xb1/0xc0 [] __do_softirq+0xf2/0x2f0 [] ? native_apic_msr_eoi_write+0x14/0x20 [] irq_exit+0x125/0x130 [] do_IRQ+0x65/0x110 [] common_interrupt+0x6e/0x6e [] ? get_page_from_freelist+0x2b8/0x750 [] ? hrtimer_try_to_cancel+0x48/0xe0 [] __alloc_pages_nodemask+0x193/0x2b0 [] ? remove_wait_queue+0x3c/0x50 [] alloc_pages_current+0xaf/0x170 [] rds_page_remainder_alloc+0x48/0x2a0 [rds] [] rds_message_copy_from_user+0x6d/0x130 [rds] [] rds_sendmsg+0x470/0x990 [rds] [] ? rw_copy_check_uvector+0xa0/0x130 [] sock_sendmsg+0x4d/0x60 [] ___sys_sendmsg+0x30a/0x330 [] ? handle_pte_fault+0x20c/0x230 [] __sys_sendmsg+0x49/0x90 [] ? syscall_trace_leave+0xf1/0x140 [] SyS_sendmsg+0x19/0x20 [] 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: [] sched_show_task+0xaf/0x120 [] rcu_check_callbacks+0x7e6/0x7f0 [] ? account_user_time+0x8b/0xa0 [] update_process_times+0x42/0x70 [] tick_sched_handle.isra.18+0x25/0x60 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x77/0x1d0 [] ? tick_sched_handle.isra.18+0x60/0x60 [] hrtimer_interrupt+0x103/0x230 [] xen_timer_interrupt+0x3d/0x170 [] ? add_interrupt_randomness+0x49/0x200 [] handle_irq_event_percpu+0x3e/0x1a0 [] handle_percpu_irq+0x3d/0x60 [] generic_handle_irq+0x2b/0x40 [] evtchn_2l_handle_events+0x26f/0x280 [] ? __do_softirq+0x18a/0x2d0 [] __xen_evtchn_do_upcall+0x4f/0x90 [] xen_evtchn_do_upcall+0x34/0x50 [] xen_hvm_callback_vector+0x6e/0x80 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: [] sched_show_task+0xaf/0x120 [] rcu_check_callbacks+0x7e6/0x7f0 [] update_process_times+0x42/0x70 [] tick_sched_handle.isra.18+0x25/0x60 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x77/0x1d0 [] ? tick_sched_handle.isra.18+0x60/0x60 [] hrtimer_interrupt+0x103/0x230 [] xen_timer_interrupt+0x3d/0x170 [] ? add_interrupt_randomness+0x49/0x200 [] handle_irq_event_percpu+0x3e/0x1a0 [] handle_percpu_irq+0x3d/0x60 [] generic_handle_irq+0x2b/0x40 [] evtchn_2l_handle_events+0x26f/0x280 [] __xen_evtchn_do_upcall+0x4f/0x90 [] xen_evtchn_do_upcall+0x34/0x50 [] xen_hvm_callback_vector+0x6e/0x80 [] ? do_audit_syscall_entry+0x67/0x70 [] syscall_trace_enter_phase1+0x143/0x1a0 [] ? __audit_syscall_exit+0x1e6/0x280 [] ? syscall_trace_leave+0xc6/0x120 [] 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: [] sched_show_task+0xaf/0x120 [] rcu_check_callbacks+0x7e6/0x7f0 [] ? account_user_time+0x8b/0xa0 [] update_process_times+0x42/0x70 [] tick_sched_handle.isra.18+0x25/0x60 [] tick_sched_timer+0x44/0x80 [] __run_hrtimer+0x77/0x1d0 [] ? tick_sched_handle.isra.18+0x60/0x60 [] hrtimer_interrupt+0x103/0x230 [] xen_timer_interrupt+0x3d/0x170 [] ? add_interrupt_randomness+0x49/0x200 [] handle_irq_event_percpu+0x3e/0x1a0 [] handle_percpu_irq+0x3d/0x60 [] generic_handle_irq+0x2b/0x40 [] evtchn_2l_handle_events+0x26f/0x280 [] __xen_evtchn_do_upcall+0x4f/0x90 [] xen_evtchn_do_upcall+0x34/0x50 [] xen_hvm_callback_vector+0x6e/0x80 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 --------------------------------------------------