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

[Oliver Sang <oliver.sang@intel.com>]

hi, Vlastimil,

On Fri, Jan 06, 2023 at 11:13:15AM +0100, Vlastimil Babka wrote:
> On 1/5/23 02:46, Oliver Sang wrote:
> > hi, Hyeonggon, hi, Vlastimil,
> > 
> > On Wed, Jan 04, 2023 at 06:04:20PM +0900, Hyeonggon Yoo wrote:
> >> On Tue, Jan 03, 2023 at 09:46:33PM +0800, Oliver Sang wrote:
> >> > On Tue, Jan 03, 2023 at 11:42:11AM +0100, Vlastimil Babka wrote:
> >> > > So the events leading up to this could be something like:
> >> > > 
> >> > > - 0x2daee is order-1 slab folio of the inode cache, sitting on the partial list
> >> > > - despite being on partial list, it's freed ???
> >> > > - somebody else allocates order-2 page 0x2daec and uses it for whatever,
> >> > > then frees it
> >> > > - 0x2daec is reallocated as order-1 slab from names_cache, then freed
> >> > > - we try to allocate from the slab page 0x2daee and trip on the PageTail
> >> > > 
> >> > > Except, the freeing of order-2 page would have reset the PageTail and
> >> > > compound_head in 0x2daec, so this is even more complicated or involves some
> >> > > extra race?
> >> > 
> >> > FYI, we ran tests more up to 500 times, then saw different issues but rate is
> >> > actually low
> >> > 
> >> > 56d5a2b9ba85a390 0af8489b0216fa1dd83e264bef8
> >> > ---------------- ---------------------------
> >> >        fail:runs  %reproduction    fail:runs
> >> >            |             |             |
> >> >            :500         12%          61:500   dmesg.invalid_opcode:#[##]
> >> >            :500          3%          14:500   dmesg.kernel_BUG_at_include/linux/mm.h
> >> >            :500          3%          17:500   dmesg.kernel_BUG_at_include/linux/page-flags.h
> >> >            :500          5%          26:500   dmesg.kernel_BUG_at_lib/list_debug.c
> >> >            :500          0%           2:500   dmesg.kernel_BUG_at_mm/page_alloc.c
> >> >            :500          0%           2:500   dmesg.kernel_BUG_at_mm/usercopy.c
> >> > 
> > 
> > hi Vlastimil,
> > 
> > as you mentioned
> >> Hm even if rate is low, the different kinds of reports could be useful to
> >> see, if all of that is caused by the commit.
> > 
> > we tried to run tests even more times, but with the config which enable
> >     CONFIG_DEBUG_PAGEALLOC
> >     CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT
> > (config is attached as
> >     config-6.1.0-rc2-00014-g0af8489b0216+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT
> > the only diff with previous config is
> > @@ -5601,7 +5601,8 @@ CONFIG_HAVE_KCSAN_COMPILER=y
> >  # Memory Debugging
> >  #
> >  CONFIG_PAGE_EXTENSION=y
> > -# CONFIG_DEBUG_PAGEALLOC is not set
> > +CONFIG_DEBUG_PAGEALLOC=y
> > +CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT=y
> >  CONFIG_PAGE_OWNER=y
> >  # CONFIG_PAGE_POISONING is not set
> >  CONFIG_DEBUG_PAGE_REF=y
> > )
> > 
> > what we found now is some issues are also reproduced on parent now (still by
> > rcutorture tests here), though seems lower rate on parent.
> > 
> > =========================================================================================
> > 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
> > 
> > 56d5a2b9ba85a390 0af8489b0216fa1dd83e264bef8
> > ---------------- ---------------------------
> >        fail:runs  %reproduction    fail:runs
> >            |             |             |
> >           8:985         19%         199:990   dmesg.invalid_opcode:#[##]
> >            :985          5%          51:990   dmesg.kernel_BUG_at_include/linux/mm.h
> >           3:985          4%          41:990   dmesg.kernel_BUG_at_include/linux/page-flags.h
> >           4:985         10%         102:990   dmesg.kernel_BUG_at_lib/list_debug.c
> >            :985          0%           2:990   dmesg.kernel_BUG_at_mm/page_alloc.c
> >           1:985          0%           3:990   dmesg.kernel_BUG_at_mm/usercopy.c
> > 
> > however, we noticed dmesg.kernel_BUG_at_include/linux/mm.h still have
> > relatively high rate on this commit but keeps clean on parent.
> 
> Well that's interesting. As long as any bugs happen in the parent, it could
> mean the commit we suspect is just changing the circumstances and creating
> conditions that increase the bug happening - e.g. because it causes slab
> pages to be always immediately freed when the last object is freed.
> 
> So I would be curiou about how some of the reports from the parent look like
> in detail.

since now we have below 3 also for parent:
           3:985          4%          41:990   dmesg.kernel_BUG_at_include/linux/page-flags.h
           4:985         10%         102:990   dmesg.kernel_BUG_at_lib/list_debug.c
           1:985          0%           3:990   dmesg.kernel_BUG_at_mm/usercopy.c
I pick one dmesg for each case from parent commit (56d5a2b9ba85a390) as
attached:
  dmesg-parent-bug-at-page-flags-h.xz
  dmesg-parent-bug-at-list_debug-c.xz
  dmesg-parent-bug-at-usercopy-c.xz
FYI

> 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

> 
>