From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-wm0-f72.google.com (mail-wm0-f72.google.com [74.125.82.72]) by kanga.kvack.org (Postfix) with ESMTP id BE4C66B0069 for ; Tue, 4 Oct 2016 10:58:23 -0400 (EDT) Received: by mail-wm0-f72.google.com with SMTP id f193so94960178wmg.0 for ; Tue, 04 Oct 2016 07:58:23 -0700 (PDT) Received: from mail-wm0-f47.google.com (mail-wm0-f47.google.com. [74.125.82.47]) by mx.google.com with ESMTPS id bm2si4964112wjc.110.2016.10.04.07.58.22 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 04 Oct 2016 07:58:22 -0700 (PDT) Received: by mail-wm0-f47.google.com with SMTP id f193so172713400wmg.0 for ; Tue, 04 Oct 2016 07:58:22 -0700 (PDT) Subject: Re: Soft lockup in __slab_free (SLUB) References: <57E8D270.8040802@kyup.com> <20160928053114.GC22706@js1304-P5Q-DELUXE> From: Nikolay Borisov Message-ID: <57F3C38C.6090203@kyup.com> Date: Tue, 4 Oct 2016 17:58:20 +0300 MIME-Version: 1.0 In-Reply-To: <20160928053114.GC22706@js1304-P5Q-DELUXE> Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit Sender: owner-linux-mm@kvack.org List-ID: To: Joonsoo Kim Cc: Linux MM , "Paul E. McKenney" On 09/28/2016 08:31 AM, Joonsoo Kim wrote: > Hello, > > Ccing Paul, because it looks like RCU problem. > > On Mon, Sep 26, 2016 at 10:46:56AM +0300, Nikolay Borisov wrote: >> Hello, >> >> On 4.4.14 stable kernel I observed the following soft-lockup, however I >> also checked that the code is the same in 4.8-rc so the problem is >> present there as well: >> >> [434575.862377] NMI watchdog: BUG: soft lockup - CPU#13 stuck for 23s! [swapper/13:0] >> [434575.866352] CPU: 13 PID: 0 Comm: swapper/13 Tainted: P O 4.4.14-clouder5 #2 >> [434575.866643] Hardware name: Supermicro X9DRD-iF/LF/X9DRD-iF, BIOS 3.0b 12/05/2013 >> [434575.866932] task: ffff8803714aadc0 ti: ffff8803714c4000 task.ti: ffff8803714c4000 >> [434575.867221] RIP: 0010:[] [] _raw_spin_unlock_irqrestore+0x1c/0x30 >> [434575.867566] RSP: 0018:ffff880373ce3dc0 EFLAGS: 00000203 >> [434575.867736] RAX: ffff88066e0c9a40 RBX: 0000000000000203 RCX: 0000000000000000 >> [434575.868023] RDX: 0000000000000008 RSI: 0000000000000203 RDI: ffff88066e0c9a40 >> [434575.868311] RBP: ffff880373ce3dc8 R08: ffff8803e5c1d118 R09: ffff8803e5c1d538 >> [434575.868609] R10: 0000000000000000 R11: ffffea000f970600 R12: ffff88066e0c9a40 >> [434575.868895] R13: ffffea000f970600 R14: 000000000046cf3b R15: ffff88036f8e3200 >> [434575.869183] FS: 0000000000000000(0000) GS:ffff880373ce0000(0000) knlGS:0000000000000000 >> [434575.869472] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 >> [434575.869643] CR2: ffffffffff600400 CR3: 0000000367201000 CR4: 00000000001406e0 >> [434575.869931] Stack: >> [434575.870095] ffff88066e0c9a40 ffff880373ce3e78 ffffffff8117ea8a ffff880373ce3e08 >> [434575.870567] 000000000046bd03 0000000100170017 ffff8803e5c1d118 ffff8803e5c1d118 >> [434575.871037] 00ff000100000000 0000000000000203 0000000000000000 ffffffff8123d9ac >> [434575.874253] Call Trace: >> [434575.874418] >> [434575.874473] [] __slab_free+0xca/0x290 >> [434575.874806] [] ? ext4_i_callback+0x1c/0x20 >> [434575.874978] [] kmem_cache_free+0x1ea/0x200 >> [434575.875149] [] ext4_i_callback+0x1c/0x20 >> [434575.875325] [] rcu_process_callbacks+0x21b/0x620 >> [434575.875506] [] __do_softirq+0x147/0x310 >> [434575.875680] [] irq_exit+0x5f/0x70 >> [434575.875851] [] smp_apic_timer_interrupt+0x42/0x50 >> [434575.876025] [] apic_timer_interrupt+0x89/0x90 >> [434575.876197] >> [434575.876250] [] ? cpuidle_enter_state+0x141/0x2c0 >> [434575.876583] [] ? cpuidle_enter_state+0x136/0x2c0 >> [434575.876755] [] cpuidle_enter+0x17/0x20 >> [434575.876929] [] cpu_startup_entry+0x2fc/0x360 >> [434575.877105] [] start_secondary+0xf3/0x100 >> >> The ip in __slab_free points to this piece of code (in mm/slub.c): >> >> if (unlikely(n)) { >> spin_unlock_irqrestore(&n->list_lock, flags); >> n = NULL; >> } >> >> I think it's a pure chance that the spin_unlock_restore is being shown in this trace, >> do you think that a cond_resched is needed in this unlikely if clause? Apparently there >> are cases where this loop can take a considerable amount of time. > > I think that __slab_free() doesn't take too long time even if there is > lock contention. And, cond_resched() is valid on softirq context? > > I think that problem would be caused by too many rcu callback is > executed without scheduling. Paul? > > Thanks. So this problem manifested itself again, with the exact same callstack, this actually leads me to believe that your hypotheses about rcu being the main culprit might actually be correct. I will have to play with ftrace to see how to acquire useful information which might point me at the culprit. Do you have any ideas on the top of your head? -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: email@kvack.org