Messages in this thread | | | Subject | Re: [rcu_sched stall] regression/miss-config ? | From | Santosh Shilimkar <> | Date | Mon, 16 May 2016 12:49:41 -0700 |
| |
On 5/16/2016 10:34 AM, Paul E. McKenney wrote: > On Mon, May 16, 2016 at 09:33:57AM -0700, Santosh Shilimkar wrote: >> On 5/16/2016 5:03 AM, Paul E. McKenney wrote: >>> On Sun, May 15, 2016 at 09:35:40PM -0700, santosh.shilimkar@oracle.com wrote: >>>> 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. >>>> >> >> [...] >> >>>>> [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] >>> >>> 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)); >> ---------------------------- > > This sounds like something to take up with the mm folks. > Sure. Will do once the link between two issues is established.
>>> 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. >> >> 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! > >> 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. > 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.
> 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
Regards, Santosh
| |