Re: BUG: Crash in __free_slab() using SLAB_TYPESAFE_BY_RCU

[Roman Gushchin <guro@fb.com>]

On Wed, Oct 02, 2019 at 12:41:29PM -0700, Roman Gushchin wrote:
> Hello, Karsten!
> 
> Thank you for the report!
> 
> On Wed, Oct 02, 2019 at 04:50:53PM +0200, Karsten Graul wrote:
> > 
> > net/smc is calling proto_register(&smc_proto, 1) with smc_proto.slab_flags = SLAB_TYPESAFE_BY_RCU.
> > Right after the last SMC socket is destroyed, proto_unregister(&smc_proto) is called, which 
> > calls kmem_cache_destroy(prot->slab). This results in a kernel crash in __free_slab().
> > Platform is s390x, reproduced on kernel 5.4-rc1. The problem was introduced by commit
> > fb2f2b0adb98 ("mm: memcg/slab: reparent memcg kmem_caches on cgroup removal")
> > 
> > I added a 'call graph', below of that is the crash log and a (simple) patch that works for me,
> > but I don't know if this is the correct way to fix it.
> > 
> > (Please keep me on CC of this thread because I do not follow the mm mailing list, thank you)
> > 
> > 
> > kmem_cache_destroy() 
> >   -> shutdown_memcg_caches()
> >     -> shutdown_cache()
> >       -> __kmem_cache_shutdown()  (slub.c)
> >         -> free_partial()
> >           -> discard_slab()
> > 	    -> free_slab()                                      -- call to __free_slab() is delayed
> > 	      -> call_rcu(rcu_free_slab)
> >     -> memcg_unlink_cache()
> >       -> WRITE_ONCE(s->memcg_params.memcg, NULL);               -- !!!
> >     -> list_add_tail(&s->list, &slab_caches_to_rcu_destroy);
> >     -> schedule_work(&slab_caches_to_rcu_destroy_work);  -> work_fn uses rcu_barrier() to wait for rcu_batch, 
> >                                                             so work_fn is not further involved here...
> > ... rcu grace period ...
> > rcu_batch()
> >   ...
> >   -> rcu_free_slab()   (slub.c)
> >     -> __free_slab()
> >       -> uncharge_slab_page()
> >         -> memcg_uncharge_slab()
> > 	  -> memcg = READ_ONCE(s->memcg_params.memcg);          -- !!! memcg == NULL
> > 	  -> mem_cgroup_lruvec(memcg)
> > 	    -> mz = mem_cgroup_nodeinfo(memcg, pgdat->node_id); -- mz == NULL
> > 	    -> lruvec = &mz->lruvec;                            -- lruvec == NULL
> > 	    -> lruvec->pgdat = pgdat;                           -- *crash*
> > 
> > The crash log:
> 
> Hm, I might be wrong, but it seems that the problem is deeper: __free_slab()
> called from the rcu path races with kmem_cache_destroy(), which is supposed
> to be called when there are no outstanding allocations (and corresponding pages).
> Any charged slab page actually holds a reference to the kmem_cache, which prevents
> its destruction (look at s->memcg_params.refcnt), but kmem_cache_destroy() ignores
> it.
> 
> If my thoughts are correct, the commit you've mentioned didn't introduced this
> issue, it just made it easier to reproduce.
> 
> The proposed fix looks dubious to me: the problem isn't in the memcg pointer
> (it's just a luck that it crashes on it), and it seems incorrect to not decrease
> the slab statistics of the original memory cgroup.
> 
> What we probably need to do instead is to extend flush_memcg_workqueue() to
> wait for all outstanding rcu free callbacks. I have to think a bit what's the best
> way to fix it. How easy is to reproduce the problem?

After a second thought, flush_memcg_workqueue() already contains
a rcu_barrier() call, so now first suspicion is that the last free() call
occurs after the kmem_cache_destroy() call. Can you, please, check if it's not
a case?

Thanks!

> 
> > 
> > 349.361168¨ Unable to handle kernel pointer dereference in virtual kernel address space
> 
> Btw, haven't you noticed anything suspicious in dmesg before this line?
> 
> Thank you!
> 
> Roman
> 
> > 349.361210¨ Failing address: 0000000000000000 TEID: 0000000000000483
> > 349.361223¨ Fault in home space mode while using kernel ASCE.
> > 349.361240¨ AS:00000000017d4007 R3:000000007fbd0007 S:000000007fbff000 P:000000000000003d
> > 349.361340¨ Oops: 0004 ilc:3 Ý#1¨ PREEMPT SMP
> > 349.361349¨ Modules linked in: tcp_diag inet_diag xt_tcpudp ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_at nf_nat iptable_mangle iptable_raw iptable_security nf_conntrack nf_defrag_ipv6 nf_de
> > 349.361436¨ CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.3.0-05872-g6133e3e4bada-dirty #14
> > 349.361445¨ Hardware name: IBM 2964 NC9 702 (z/VM 6.4.0)
> > 349.361450¨ Krnl PSW : 0704d00180000000 00000000003cadb6 (__free_slab+0x686/0x6b0)
> > 349.361464¨            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 RI:0 EA:3
> > 349.361470¨ Krnl GPRS: 00000000f3a32928 0000000000000000 000000007fbf5d00 000000000117c4b8
> > 349.361475¨            0000000000000000 000000009e3291c1 0000000000000000 0000000000000000
> > 349.361481¨            0000000000000003 0000000000000008 000000002b478b00 000003d080a97600
> > 349.361481¨            0000000000000003 0000000000000008 000000002b478b00 000003d080a97600
> > 349.361486¨            000000000117ba00 000003e000057db0 00000000003cabcc 000003e000057c78
> > 349.361500¨ Krnl Code: 00000000003cada6: e310a1400004        lg      %r1,320(%r10)
> > 349.361500¨            00000000003cadac: c0e50046c286        brasl   %r14,ca32b8
> > 349.361500¨           #00000000003cadb2: a7f4fe36            brc     15,3caa1e
> > 349.361500¨           >00000000003cadb6: e32060800024        stg     %r2,128(%r6)
> > 349.361500¨            00000000003cadbc: a7f4fd9e            brc     15,3ca8f8
> > 349.361500¨            00000000003cadc0: c0e50046790c        brasl   %r14,c99fd8
> > 349.361500¨            00000000003cadc6: a7f4fe2c            brc     15,3caa
> > 349.361500¨            00000000003cadc6: a7f4fe2c            brc     15,3caa1e
> > 349.361500¨            00000000003cadca: ecb1ffff00d9        aghik   %r11,%r1,-1
> > 349.361619¨ Call Trace:
> > 349.361627¨ (Ý<00000000003cabcc>¨ __free_slab+0x49c/0x6b0)
> > 349.361634¨  Ý<00000000001f5886>¨ rcu_core+0x5a6/0x7e0
> > 349.361643¨  Ý<0000000000ca2dea>¨ __do_softirq+0xf2/0x5c0
> > 349.361652¨  Ý<0000000000152644>¨ irq_exit+0x104/0x130
> > 349.361659¨  Ý<000000000010d222>¨ do_IRQ+0x9a/0xf0
> > 349.361667¨  Ý<0000000000ca2344>¨ ext_int_handler+0x130/0x134
> > 349.361674¨  Ý<0000000000103648>¨ enabled_wait+0x58/0x128
> > 349.361681¨ (Ý<0000000000103634>¨ enabled_wait+0x44/0x128)
> > 349.361688¨  Ý<0000000000103b00>¨ arch_cpu_idle+0x40/0x58
> > 349.361695¨  Ý<0000000000ca0544>¨ default_idle_call+0x3c/0x68
> > 349.361704¨  Ý<000000000018eaa4>¨ do_idle+0xec/0x1c0
> > 349.361748¨  Ý<000000000018ee0e>¨ cpu_startup_entry+0x36/0x40
> > 349.361756¨  Ý<000000000122df34>¨ arch_call_rest_init+0x5c/0x88
> > 349.361761¨  Ý<0000000000000000>¨ 0x0
> > 349.361765¨ INFO: lockdep is turned off.
> > 349.361769¨ Last Breaking-Event-Address:
> > 349.361774¨  Ý<00000000003ca8f4>¨ __free_slab+0x1c4/0x6b0
> > 349.361781¨ Kernel panic - not syncing: Fatal exception in interrupt
> > 
> > 
> > A fix that works for me (RFC):
> > 
> > diff --git a/mm/slab.h b/mm/slab.h
> > index a62372d0f271..b19a3f940338 100644
> > --- a/mm/slab.h
> > +++ b/mm/slab.h
> > @@ -328,7 +328,7 @@ static __always_inline void memcg_uncharge_slab(struct page *page, int order,
> > 
> >         rcu_read_lock();
> >         memcg = READ_ONCE(s->memcg_params.memcg);
> > -       if (likely(!mem_cgroup_is_root(memcg))) {
> > +       if (likely(memcg && !mem_cgroup_is_root(memcg))) {
> >                 lruvec = mem_cgroup_lruvec(page_pgdat(page), memcg);
> >                 mod_lruvec_state(lruvec, cache_vmstat_idx(s), -(1 << order));
> >                 memcg_kmem_uncharge_memcg(page, order, memcg);
> > 
> > -- 
> > Karsten
> > 
> > (I'm a dude)
> > 
> >