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

[Wang Yugui <wangyugui@e16-tech.com>]

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);
}


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_al
 go_bit t
 tm
[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
> 
> 
> 
>