Re: [linus:master] [mm, slub] 0af8489b02: kernel_BUG_at_include/linux/mm.h

From: Feng Tang
Date: Tue Jan 10 2023 - 21:29:55 EST

On Tue, Jan 10, 2023 at 10:09:36PM +0800, Vlastimil Babka wrote:
> On 1/10/23 14:53, Oliver Sang wrote:
> > hi all,
> >
> > On Mon, Jan 09, 2023 at 10:01:15PM +0800, Oliver Sang wrote:
> >>
> >> On Fri, Jan 06, 2023 at 11:13:15AM +0100, Vlastimil Babka wrote:
> >>
> >> > And if the rate at the parent (has it increased thanks to the
> >> > DEBUG_PAGEALLOC?) is sufficient to bisect to the truly first bad commit. Thanks!
> >>
> >> got it. Thanks for suggestion!
> >>
> >> since 0af8489b02 is based on v6.1-rc2, we will test (both rectorture and boot)
> >> with same config upon v6.1-rc2 to see if it's really clean there.
> >> if so we will use dmesg.invalid_opcode:#[##] to trigger new bisect.
> >>
> >> will keep you updated. Thanks
> >
> > by more tests, we cannot make sure the v6.1-rc2 is clean, so we also checked
> > v6.1-rc1 and v6.0. from results, we have low confidence that we can make a
> > successful bisection based on them [1][2]. could you suggest?
>
> So am I reading it right, that the probleam appears to be introduced between
> v6.0 (0 failures) and v6.1-rc1 (>0 failures)? But agree that with such low
> incidence, it's hard to bisect.

Yes, it's hard for bisection, as it happens at a higher reproduce rate
on several commits, hope it could be bisected soon.

Before Oliver found the parent commit also trigger the problem, I did
some debug, and I think related factors could be compound_page, folio,
slub and i386(struct page size and layout), which cause some compound
page structures corrupted.

* I tried change the slub_max_order to 0 for SLUB_TINY (much less
compound-page operations), and no issue is found for 350 runs.

* Disable order>=1 in pcp list, the issue's reproduce rate keeps
similar, which means the pcp operation is not related.

* Tried add some debug info in unused members of struct page of tail
pages (not first tail page), or add one more member at the end of
'struct page', can't reproduce it.

>From Oliver's reports, there are several kinds of errors: list
operation failure (list_head structure corruption), compound page
check failure (PageTail warning) etc, which seem to indicate the
struct pages are randomly corrupted. In dump_page(), I tired to dump
more pages befor and after 'raw' and 'head' pages

[ 18.265162][ T186] page:43caddc9 refcount:1 mapcount:0 mapping:00000000 index:0xedece900 pfn:0x2dece
[ 18.266205][ T186] head:5e92e8e2 order:1 compound_mapcount:0 compound_pincount:0
[ 18.266928][ T186] flags: 0x10200(slab|head|zone=0)
[ 18.267339][ T186] raw-2: 00010200 c0100b70 c0100b70 c01a0680 edecd000 00020001 ffffffff 00000001
[ 18.268055][ T186] raw-2: 00000000 00000000
[ 18.268419][ T186] raw-1: 00000000 e7652fe1 00000101 ffffffff 00000000 00000000 ffffffff 00000000
[ 18.269124][ T186] raw-1: 00000000 00000000
[ 18.269488][ T186] raw: 00010200 e7652fe1 c0100bf0 00000400 edece900 000a0003 ffffffff 00000001
[ 18.270187][ T186] raw: edce5f81 00000000
[ 18.270534][ T186] raw1: 00000000 e7653031 00000101 ffffffff 00000000 00000000 ffffffff 00000000
[ 18.271257][ T186] raw1: 00000000 00000000
[ 18.271617][ T186] raw2: 00010200 00000100 00000122 c01a0780 00000000 000a000a ffffffff 00000001
[ 18.272330][ T186] raw2: edd5bf01 00000000
[ 18.272690][ T186] raw3: 00000000 e7653081 00000101 ffffffff 00000000 00000000 ffffffff 00000000
[ 18.273424][ T186] raw3: 00000000 00000000

[ 18.273793][ T186] head: 00010200 c0100b70 c0100b70 c01a0680 edecd000 00020001 ffffffff 00000001
[ 18.274534][ T186] head: 00000000 00000000
[ 18.274909][ T186] head1: 00000000 e7652fe1 00000101 ffffffff 00000000 00000000 ffffffff 00000000
[ 18.275633][ T186] head1: 00000000 00000000
[ 18.275996][ T186] head2: 00010200 e7652fe1 c0100bf0 00000400 edece900 000a0003 ffffffff 00000001
[ 18.276725][ T186] head2: edce5f81 00000000
[ 18.277093][ T186] head3: 00000000 e7653031 00000101 ffffffff 00000000 00000000 ffffffff 00000000
[ 18.277820][ T186] head3: 00000000 00000000
[ 18.278182][ T186] page dumped because: VM_BUG_ON_PAGE(PageTail(page))
[ 18.278747][ T186] page_owner tracks the page as allocated
[ 18.279447][ T186] page last allocated via order 1, migratetype Unmovable, gfp_mask 0xd20c0(__GFP_IO|__GFP_FS|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC), pid 186, tgid 186 (udevadm), ts 18262675212, free_ts 18262044539
...

The page 'head' is actually 'raw' - 2, while page 'raw' seems
corrupted as it has PG_head bit set, while PageTail() is also true.

Another problem is 'raw-1' and 'raw' both points to 'raw-2', and
if it is an order-2 compound page, the 'raw+1' should also points
to 'raw-2' as 3 tail pages point to one head page. Or there is some
switch(corrupted) between order-1 and order-2, as Vlastimil
supsected in earlier reply?

Thanks,
Feng

> > a further information not sure if it's helpful, [1][2] are both i386 based.
> > we also tried to run boot tests on x86_64 upon commit 0af8489b02, whatever
> > with or without CONFIG_DEBUG_PAGEALLOC/CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT,
> > we never obseve similar issues (also run 999 times).
>
> Yeah it looks very much like something that manifests only on i386 (perhaps
> only in QEMU as well?) and never x86_64.
>
> What might be interesting then is v6.1-rc1 with further modified config to
> enabled CONFIG_SLUB_DEBUG and CONFIG_SLUB_DEBUG_ON. Maybe it will catch the
> culprit sooner. Or maybe it will obscure the bug instead, unfortunately.
>
> Thanks for all your effort!
>
> > [1]
> > boot results:
> > =========================================================================================
> > compiler/kconfig/rootfs/sleep/tbox_group/testcase:
> > gcc-11/i386-randconfig-a012-20221226+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT/debian-11.1-i386-20220923.cgz/1/vm-snb/boot
> >
> > v6.0 v6.1-rc1 v6.1-rc2 56d5a2b9ba85a390473e86b4fe4 0af8489b0216fa1dd83e264bef8
> > ---------------- --------------------------- --------------------------- --------------------------- ---------------------------
> > fail:runs %reproduction fail:runs %reproduction fail:runs %reproduction fail:runs %reproduction fail:runs
> > | | | | | | | | |
> > :999 0% 2:999 0% 1:999 1% 11:999 21% 208:999 dmesg.invalid_opcode:#[##]
> > :999 0% :999 0% :999 0% 2:999 5% 51:999 dmesg.kernel_BUG_at_include/linux/mm.h
> > :999 0% 1:999 0% :999 0% 4:999 4% 40:999 dmesg.kernel_BUG_at_include/linux/page-flags.h
> > :999 0% 1:999 0% 1:999 0% 4:999 11% 111:999 dmesg.kernel_BUG_at_lib/list_debug.c
> > :999 0% :999 0% :999 0% :999 0% 2:999 dmesg.kernel_BUG_at_mm/page_alloc.c
> > :999 0% :999 0% :999 0% 1:999 0% 3:999 dmesg.kernel_BUG_at_mm/usercopy.c
> >
> > [2]
> > rcutorture results:
> > =========================================================================================
> > compiler/kconfig/rootfs/runtime/tbox_group/test/testcase/torture_type:
> > gcc-11/i386-randconfig-a012-20221226+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT/debian-11.1-i386-20220923.cgz/300s/vm-snb/default/rcutorture/tasks-tracing
> >
> > v6.0 v6.1-rc1 v6.1-rc2 56d5a2b9ba85a390473e86b4fe4 0af8489b0216fa1dd83e264bef8
> > ---------------- --------------------------- --------------------------- --------------------------- ---------------------------
> > fail:runs %reproduction fail:runs %reproduction fail:runs %reproduction fail:runs %reproduction fail:runs
> > | | | | | | | | |
> > :999 0% 3:999 0% :999 1% 8:998 20% 200:999 dmesg.invalid_opcode:#[##]
> > :999 0% :999 0% :999 0% :998 5% 51:999 dmesg.kernel_BUG_at_include/linux/mm.h
> > :999 0% :999 0% :999 0% 3:998 4% 42:999 dmesg.kernel_BUG_at_include/linux/page-flags.h
> > :999 0% 3:999 0% :999 0% 4:998 10% 102:999 dmesg.kernel_BUG_at_lib/list_debug.c
> > :999 0% :999 0% :999 0% :998 0% 2:999 dmesg.kernel_BUG_at_mm/page_alloc.c
> > :999 0% :999 0% :999 0% 1:998 0% 3:999 dmesg.kernel_BUG_at_mm/usercopy.c
> >
> >>
> >> >
> >> >
>
>