Re: kernel BUG at mm/huge_memory.c:2736(linux 5.10.29)

[Yang Shi <shy828301@gmail.com>]

On Fri, Apr 23, 2021 at 1:07 AM Wang Yugui <wangyugui@e16-tech.com> wrote:
>
> Hi,
>
> > With this patch, the problem yet not happen after 4 tests(5.10.x).
>
> With this patch , another problem happened at 6th test.
>
> kernel BUG at mm/huge_memory.c:2343!
> static void unmap_page(struct page *page)
> {
>     enum ttu_flags ttu_flags = TTU_IGNORE_MLOCK |
>         TTU_RMAP_LOCKED | TTU_SPLIT_HUGE_PMD;
>     bool unmap_success;
>
>     VM_BUG_ON_PAGE(!PageHead(page), page);
>
>     if (PageAnon(page))
>         ttu_flags |= TTU_SPLIT_FREEZE;
>
>     unmap_success = try_to_unmap(page, ttu_flags);
> L2343:VM_BUG_ON_PAGE(!unmap_success,page);

Thanks for running the test. This is what I expected from the debug
patch. It means try_to_unmap() didn't unmap the huge page
successfully. The huge page is PTE-mapped, try_to_unmap() is supposed
to unmap every mapped subpage. But it seems it didn't unmap any
subpage at all (the refcount of the huge page is 512 per the log from
earlier email).

By reading the code, I didn't figure out what went wrong yet. You
mentioned that the 5.4.x kernel is fine, so may you try to do some
bisect?

> }
>
>
> This is the full dmesg output.
>
> T7610 login: [59085.082973] page:000000008becb0e6 refcount:512 mapcount:0 mapping:0000000000000000 index:0x7f3eb7382 pfn:0x2804a00
> [59085.093430] head:000000008becb0e6 order:9 compound_mapcount:0 compound_pincount:0
> [59085.100999] anon flags: 0x57ffffc009001d(locked|uptodate|dirty|lru|head|swapbacked)
> [59085.108750] raw: 0057ffffc009001d ffffc140640e0008 ffffc1405fc80008 ffff8afa82038581
> [59085.116572] raw: 00000007f3eb7382 0000000000000000 00000200ffffffff ffff8b05c2a1c000
> [59085.124388] page dumped because: VM_BUG_ON_PAGE(!unmap_success)
> [59085.130361] page->mem_cgroup:ffff8b05c2a1c000
> [59085.134766] ------------[ cut here ]------------
> [59085.139426] kernel BUG at mm/huge_memory.c:2343!
> [59085.144091] invalid opcode: 0000 [#1] SMP NOPTI
> [59085.145083] CPU: 19 PID: 377 Comm: kswapd1 Tainted: G S                5.10.32-2.el7.x86_64 #1
> [59085.145083] Hardware name: Dell Inc. Precision T7610/0NK70N, BIOS A18 09/11/2019
> [59085.145083] RIP: 0010:split_huge_page_to_list+0x7a2/0xb30
> [59085.145083] Code: e8 b3 be fc ff e9 42 fb ff ff 48 c7 c6 98 6b 3a 98 4c 89 e7 e8 bf 7f f9 ff 0f 0b 48 c7 c6 88 f5 3a 98 4c 89 e7 e8 ae 7f f9 ff <0f> 0b 48 c7 c6 a8 f5 3a 98 4c 89 e7 e8 9d 7f f9 ff 0f 0b 49 8b 54
> [59085.145083] RSP: 0018:ffff9a234d183b10 EFLAGS: 00010286
> [59085.145083] RAX: 0000000000000000 RBX: ffff8b05c2a1cae0 RCX: 0000000000000000
> [59085.145083] RDX: 0000000000000000 RSI: ffff8b156fa58a80 RDI: ffff8b156fa58a80
> [59085.145083] RBP: ffffc14060128080 R08: 0000000000000000 R09: c0000000ffffbfff
> [59085.145083] R10: 0000000000000001 R11: ffff9a234d1837e8 R12: ffffc14060128000
> [59085.145083] R13: 0000000000000000 R14: ffff8afa82038580 R15: ffff8b15affd3000
> [59085.145083] FS:  0000000000000000(0000) GS:ffff8b156fa40000(0000) knlGS:0000000000000000
> [59085.145083] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [59085.145083] CR2: 00007f5c226c01a8 CR3: 00000020792b6006 CR4: 00000000001706e0
> [59085.145083] Call Trace:
> [59085.145083]  ? free_unref_page_commit+0x9b/0x110
> [59085.145083]  deferred_split_scan+0x1ca/0x320
> [59085.145083]  do_shrink_slab+0x11f/0x250
> [59085.145083]  shrink_slab+0x20f/0x2c0
> [59085.145083]  shrink_node+0x24b/0x6d0
> [59085.145083]  balance_pgdat+0x2db/0x550
> [59085.145083]  kswapd+0x201/0x390
> [59085.145083]  ? finish_wait+0x80/0x80
> [59085.145083]  ? balance_pgdat+0x550/0x550
> [59085.145083]  kthread+0x116/0x130
> [59085.145083]  ? kthread_park+0x80/0x80
> [59085.145083]  ret_from_fork+0x1f/0x30
> [59085.145083] Modules linked in: rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache rfkill rpcrdma ib_isert iscsi_target_mod ib_iser libiscsi scsi_transport_iscsi ib_srpt target_core_mod ib_srp scsi_transport_srp ib_ipoib rdma_ucm ib_umad snd_hda_codec_realtek intel_rapl_msr snd_hda_codec_generic intel_rapl_common ledtrig_audio snd_hda_codec_hdmi snd_hda_intel snd_intel_dspcfg soundwire_intel soundwire_generic_allocation snd_soc_core sb_edac x86_pkg_temp_thermal snd_compress intel_powerclamp snd_pcm_dmaengine coretemp soundwire_cadence iTCO_wdt dcdbas intel_pmc_bxt mei_hdcp mei_wdt iTCO_vendor_support snd_hda_codec dell_smm_hwmon kvm_intel snd_hda_core ac97_bus snd_hwdep snd_seq kvm snd_seq_device irqbypass snd_pcm rapl snd_timer mei_me intel_cstate i2c_i801 intel_uncore i2c_smbus mei lpc_ich snd soundcore nvme_rdma nvme_fabrics rdma_cm iw_cm ib_cm nfsd rdmavt rdma_rxe ib_uverbs ip6_udp_tunnel auth_rpcgss udp_tunnel ib_core nfs_acl lockd grace nfs_ssc ip_tables xfs radeon i2c_algo_bit ttm
> [59085.145083]  drm_kms_helper cec bnx2x crct10dif_pclmul crc32_pclmul crc32c_intel nvme drm ghash_clmulni_intel mpt3sas e1000e pcspkr mdio nvme_core raid_class scsi_transport_sas wmi dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua btrfs xor raid6_pq sunrpc i2c_dev
> [59085.410667] ---[ end trace c12d9c5dce775958 ]---
> [59085.583739] RIP: 0010:split_huge_page_to_list+0x7a2/0xb30
> [59085.589189] Code: e8 b3 be fc ff e9 42 fb ff ff 48 c7 c6 98 6b 3a 98 4c 89 e7 e8 bf 7f f9 ff 0f 0b 48 c7 c6 88 f5 3a 98 4c 89 e7 e8 ae 7f f9 ff <0f> 0b 48 c7 c6 a8 f5 3a 98 4c 89 e7 e8 9d 7f f9 ff 0f 0b 49 8b 54
> [59085.608129] RSP: 0018:ffff9a234d183b10 EFLAGS: 00010286
> [59085.613405] RAX: 0000000000000000 RBX: ffff8b05c2a1cae0 RCX: 0000000000000000
> [59085.620606] RDX: 0000000000000000 RSI: ffff8b156fa58a80 RDI: ffff8b156fa58a80
> [59085.627806] RBP: ffffc14060128080 R08: 0000000000000000 R09: c0000000ffffbfff
> [59085.635016] R10: 0000000000000001 R11: ffff9a234d1837e8 R12: ffffc14060128000
> [59085.642218] R13: 0000000000000000 R14: ffff8afa82038580 R15: ffff8b15affd3000
> [59085.649422] FS:  0000000000000000(0000) GS:ffff8b156fa40000(0000) knlGS:0000000000000000
> [59085.657588] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [59085.663388] CR2: 00007f5c226c01a8 CR3: 00000020792b6006 CR4: 00000000001706e0
> [59085.670590] Kernel panic - not syncing: Fatal exception
> [59085.671587] Kernel Offset: 0x16000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
> [59085.671587] ---[ end Kernel panic - not syncing: Fatal exception ]---
>
>
> Best Regards
> Wang Yugui (wangyugui@e16-tech.com)
> 2021/04/23
>
> > Hi,
> >
> > > On Sat, Apr 17, 2021 at 1:33 AM Wang Yugui <wangyugui@e16-tech.com> wrote:
> > > >
> > > > Hi,
> > > >
> > > > > On Mon, Apr 12, 2021 at 3:07 AM Wang Yugui <wangyugui@e16-tech.com> wrote:
> > > > > >
> > > > > > Hi,
> > > > > >
> > > > > > kernel BUG at mm/huge_memory.c:2736(linux 5.10.29) is triggered
> > > > > > by some files write test.
> > > > > >
> > > > > > mm/huge_memory.c:
> > > > > >         if (IS_ENABLED(CONFIG_DEBUG_VM) && mapcount) {
> > > > > >             pr_alert("total_mapcount: %u, page_count(): %u\n",
> > > > > >                     mapcount, count);
> > > > > >             if (PageTail(page))
> > > > > >                 dump_page(head, NULL);
> > > > > >             dump_page(page, "total_mapcount(head) > 0");
> > > > > > L2736:           BUG();
> > > > > >         }
> > > > >
> > > > > We just can tell the mapcount of the page is not zero from the current
> > > > > log, it might mean the unmap_page() call is failed. It seems you have
> > > > > CONFIG_DEBUG_VM enabled, could you please paste more log? There is
> > > > > "VM_BUG_ON_PAGE(!unmap_success, page)" in unmap_page(). It should be
> > > > > able to tell us if unmap_page() is failed or not, or something else
> > > > > happened.
> > > >
> > > > This is the full dmesg output
> > > >
> > > > [63080.331513] huge_memory: total_mapcount: 511, page_count(): 512
> > > > [63080.332167] page:00000000d2e1a982 refcount:512 mapcount:0 mapping:0000000000000000 index:0x7fe260582 pfn:0x676a00
> > > > [63080.332167] head:00000000d2e1a982 order:9 compound_mapcount:0 compound_pincount:0
> > > > [63080.332167] anon flags: 0x17ffffc009001d(locked|uptodate|dirty|lru|head|swapbacked)
> > > > [63080.332167] raw: 0017ffffc009001d ffffc93cda0d0008 ffffc93cd9ab0008 ffff8f21be9f0cb9
> > > > [63080.332167] raw: 00000007fe260582 0000000000000000 00000200ffffffff ffff8f1021810000
> > > > [63080.332167] page->mem_cgroup:ffff8f1021810000
> > > > [63080.332167] page:00000000bc78ac24 refcount:512 mapcount:1 mapping:0000000000000000 index:0x7fe260584 pfn:0x676a02
> > > > [63080.332167] head:00000000d2e1a982 order:9 compound_mapcount:0 compound_pincount:0
> > > > [63080.332167] anon flags: 0x17ffffc009001d(locked|uptodate|dirty|lru|head|swapbacked)
> > > > [63080.332167] raw: 0017ffffc0000000 ffffc93cd9da8001 dead000000000000 ffffc93d428d0098
> > > > [63080.332167] raw: ffffa002cd183bf0 0000000000000000 0000000000000000 0000000000000000
> > > > [63080.332167] head: 0017ffffc009001d ffffc93cda0d0008 ffffc93cd9ab0008 ffff8f21be9f0cb9
> > > > [63080.332167] head: 00000007fe260582 0000000000000000 00000200ffffffff ffff8f1021810000
> > > > [63080.332167] page dumped because: total_mapcount(head) > 0
> > >
> > > Added Kirill in this loop too, he may have some insights.
> > >
> > > Thanks a lot for pasting the full log. It seems the BUG_ON in
> > > unmap_page() and VM_BUG_ON_PAGE(compound_mapcount(head), head) were
> > > not triggered. But the dumped page shows its total_mapcount is 511. It
> > > means 511 subpages of the huge page are PTE mapped. It seems all tail
> > > pages are PTE mapped. It may be because unmap_page() is failed or they
> > > are mapped again after unmap_page().
> > >
> > > But the VM_BUG_ON_PAGE just checks compound_mapcount, and it seems
> > > page_mapcount() call in unmap_page() also just checks
> > > compound_mapcount and the mapcount of the head page. If the mapcount
> > > of the head page is 0 and compound_mapcount is also 0, try_to_unmap()
> > > considers unmap is successful.
> > >
> > > So we can't tell which case it is although I don't think of how
> > > unmap_page() could fail for this case.  I think we should check the
> > > total mapcount in try_to_unmap() instead.
> > >
> > > Can you please try the below debug patch (untested) to help narrow
> > > down the problem?
> > >
> > > diff --git a/mm/huge_memory.c b/mm/huge_memory.c
> > > index ae907a9c2050..c10e89be1c99 100644
> > > --- a/mm/huge_memory.c
> > > +++ b/mm/huge_memory.c
> > > @@ -2726,7 +2726,7 @@ int split_huge_page_to_list(struct page *page,
> > > struct list_head *list)
> > >         }
> > >
> > >         unmap_page(head);
> > > -       VM_BUG_ON_PAGE(compound_mapcount(head), head);
> > > +       VM_BUG_ON_PAGE(total_mapcount(head), head);
> > >
> > >         /* block interrupt reentry in xa_lock and spinlock */
> > >         local_irq_disable();
> > > diff --git a/mm/rmap.c b/mm/rmap.c
> > > index b0fc27e77d6d..537dfc557744 100644
> > > --- a/mm/rmap.c
> > > +++ b/mm/rmap.c
> > > @@ -1777,7 +1777,7 @@ bool try_to_unmap(struct page *page, enum ttu_flags flags)
> > >         else
> > >                 rmap_walk(page, &rwc);
> > >
> > > -       return !page_mapcount(page) ? true : false;
> > > +       return !total_mapcount(page) ? true : false;
> > >  }
> > >
> > >  /**
> > >
> > >
> >
> > With this patch, the problem yet not happen after 4 tests(5.10.x).
> >
> > By the way, the problem does not happen in 5.4.x.(>about 120 tests)
> > does this match the code version?
> >
> > Best Regards
> > Wang Yugui (wangyugui@e16-tech.com)
> > 2021/04/23
> >
> >
> >
> >
>
>