v4.6 kernel BUG at mm/rmap.c:1101!

Hi,

After upgrading kernel of my desktop system from v4.6-rc7 to v4.6, I've started seeing following:

[176611.093747] page:ffffea0000360000 count:1 mapcount:0 mapping:ffff880034d2e0a1 index:0x1f9b06600 compound_mapcount: 0
[176611.093751] flags: 0x3fff8000044079(locked|uptodate|dirty|lru|active|head|swapbacked)
[176611.093752] page dumped because: VM_BUG_ON_PAGE(page->index != linear_page_index(vma, address))
[176611.093753] page->mem_cgroup:ffff88049e81b800
[176611.093765] ------------[ cut here ]------------
[176611.093778] kernel BUG at mm/rmap.c:1101!
[176611.093787] invalid opcode: 0000 [#1] PREEMPT SMP 
[176611.093800] Modules linked in: vfat fat usb_storage fuse bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables pl2303 snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic snd_hda_intel snd_hda_codec x86_pkg_temp_thermal coretemp kvm_intel snd_hwdep snd_hda_core kvm snd_seq snd_seq_device iTCO_wdt iTCO_vendor_support snd_pcm mxm_wmi irqbypass crct10dif_pclmul joydev crc32_pclmul crc32c_intel mei_me snd_timer ghash_clmulni_intel snd mei lpc_ich i2c_i801 shpchp mfd_core soundcore wmi i915 drm_kms_helper drm e1000e igb serio_raw dca i2c_algo_bit i2c_core ptp pps_core video
[176611.093947] CPU: 1 PID: 2851 Comm: BrowserBlocking Tainted: G          I     4.6.0 #71
[176611.093962] Hardware name: Gigabyte Technology Co., Ltd. Z87X-UD7 TH/Z87X-UD7 TH-CF, BIOS F4 03/18/2014
[176611.093981] task: ffff880492193600 ti: ffff8804971e0000 task.ti: ffff8804971e0000
[176611.093996] RIP: 0010:[<ffffffff811dbcb3>]  [<ffffffff811dbcb3>] page_move_anon_rmap+0x93/0xa0
[176611.094018] RSP: 0000:ffff8804971e3d58  EFLAGS: 00010296
[176611.094030] RAX: 0000000000000021 RBX: ffffea0000360000 RCX: 0000000000000002
[176611.094045] RDX: 0000000080000002 RSI: ffffffff81a2dce2 RDI: 00000000ffffffff
[176611.094059] RBP: ffff8804971e3d70 R08: 0000000000016e39 R09: 0000000000000004
[176611.094074] R10: 800000000d81f065 R11: ffffffff81f19c4e R12: ffff880034d2e0a0
[176611.094088] R13: 00000001f9b06600 R14: ffffea00003607c0 R15: ffff880495b3bc00
[176611.094103] FS:  00007f0a91e71700(0000) GS:ffff8804af240000(0000) knlGS:0000000000000000
[176611.094119] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[176611.094131] CR2: 00001f9b0661fcc8 CR3: 0000000497097000 CR4: 00000000001406e0
[176611.094146] Stack:
[176611.094151]  ffff880042301398 00001f9b0661fcc8 ffffea0011c746b0 ffff8804971e3df8
[176611.094169]  ffffffff811ccdd7 000000000000000c ffff880471d1a0f8 ffff880498d2f198
[176611.094186]  0000000000000001 ffff8804971e3e50 ffffffff8119b156 0000000000000001
[176611.094203] Call Trace:
[176611.094213]  [<ffffffff811ccdd7>] do_wp_page+0x487/0x710
[176611.094225]  [<ffffffff8119b156>] ? generic_file_read_iter+0x606/0x6f0
[176611.094238]  [<ffffffff811cf1e9>] handle_mm_fault+0xf59/0x1d30
[176611.094252]  [<ffffffff8121eef7>] ? __vfs_read+0xa7/0xd0
[176611.094266]  [<ffffffff81066298>] __do_page_fault+0x1a8/0x520
[176611.094280]  [<ffffffff81066632>] do_page_fault+0x22/0x30
[176611.094295]  [<ffffffff81759508>] page_fault+0x28/0x30
[176611.094306] Code: 20 05 a1 81 e8 2f d0 fe ff 0f 0b e8 68 ce fe ff 0f 0b 48 89 d6 e8 ee 32 01 00 eb cd 48 c7 c6 b0 2e a1 81 48 89 df e8 0d d0 fe ff <0f> 0b 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 
[176611.094386] RIP  [<ffffffff811dbcb3>] page_move_anon_rmap+0x93/0xa0
[176611.094400]  RSP <ffff8804971e3d58>
[176611.099920] ---[ end trace d9cb6b7ad0bd6c55 ]---
[176611.099922] note: BrowserBlocking[2851] exited with preempt_count 1

I haven't bisected this yet but there seems to be only one commit touching mm in v4.6 so I kind of suspect that it has something to do with the issue. I'll try to revert it next and see if that changes anything.

I've seen the issue now few times but I have no easy means to reproduce it. Only thing that seems to be consistent is the fact that the running process is always chrome.

The commit in question is:

6d0a07edd17c ("mm: thp: calculate the mapcount correctly for THP pages during WP faults").

Does this ring any bells? Thanks in advance.

Quoted 53 lines · Mika Westerberg

Hi,

After upgrading kernel of my desktop system from v4.6-rc7 to v4.6, I've started seeing following:

[176611.093747] page:ffffea0000360000 count:1 mapcount:0 mapping:ffff880034d2e0a1 index:0x1f9b06600 compound_mapcount: 0
[176611.093751] flags: 0x3fff8000044079(locked|uptodate|dirty|lru|active|head|swapbacked)
[176611.093752] page dumped because: VM_BUG_ON_PAGE(page->index != linear_page_index(vma, address))
[176611.093753] page->mem_cgroup:ffff88049e81b800
[176611.093765] ------------[ cut here ]------------
[176611.093778] kernel BUG at mm/rmap.c:1101!
[176611.093787] invalid opcode: 0000 [#1] PREEMPT SMP 
[176611.093800] Modules linked in: vfat fat usb_storage fuse bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables pl2303 snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic snd_hda_intel snd_hda_codec x86_pkg_temp_thermal coretemp kvm_intel snd_hwdep snd_hda_core kvm snd_seq snd_seq_device iTCO_wdt iTCO_vendor_support snd_pcm mxm_wmi irqbypass crct10dif_pclmul joydev crc32_pclmul crc32c_intel mei_me snd_timer ghash_clmulni_intel snd mei lpc_ich i2c_i801 shpchp mfd_core soundcore wmi i915 drm_kms_helper drm e1000e igb serio_raw dca i2c_algo_bit i2c_core ptp pps_core video
[176611.093947] CPU: 1 PID: 2851 Comm: BrowserBlocking Tainted: G          I     4.6.0 #71
[176611.093962] Hardware name: Gigabyte Technology Co., Ltd. Z87X-UD7 TH/Z87X-UD7 TH-CF, BIOS F4 03/18/2014
[176611.093981] task: ffff880492193600 ti: ffff8804971e0000 task.ti: ffff8804971e0000
[176611.093996] RIP: 0010:[<ffffffff811dbcb3>]  [<ffffffff811dbcb3>] page_move_anon_rmap+0x93/0xa0
[176611.094018] RSP: 0000:ffff8804971e3d58  EFLAGS: 00010296
[176611.094030] RAX: 0000000000000021 RBX: ffffea0000360000 RCX: 0000000000000002
[176611.094045] RDX: 0000000080000002 RSI: ffffffff81a2dce2 RDI: 00000000ffffffff
[176611.094059] RBP: ffff8804971e3d70 R08: 0000000000016e39 R09: 0000000000000004
[176611.094074] R10: 800000000d81f065 R11: ffffffff81f19c4e R12: ffff880034d2e0a0
[176611.094088] R13: 00000001f9b06600 R14: ffffea00003607c0 R15: ffff880495b3bc00
[176611.094103] FS:  00007f0a91e71700(0000) GS:ffff8804af240000(0000) knlGS:0000000000000000
[176611.094119] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[176611.094131] CR2: 00001f9b0661fcc8 CR3: 0000000497097000 CR4: 00000000001406e0
[176611.094146] Stack:
[176611.094151]  ffff880042301398 00001f9b0661fcc8 ffffea0011c746b0 ffff8804971e3df8
[176611.094169]  ffffffff811ccdd7 000000000000000c ffff880471d1a0f8 ffff880498d2f198
[176611.094186]  0000000000000001 ffff8804971e3e50 ffffffff8119b156 0000000000000001
[176611.094203] Call Trace:
[176611.094213]  [<ffffffff811ccdd7>] do_wp_page+0x487/0x710
[176611.094225]  [<ffffffff8119b156>] ? generic_file_read_iter+0x606/0x6f0
[176611.094238]  [<ffffffff811cf1e9>] handle_mm_fault+0xf59/0x1d30
[176611.094252]  [<ffffffff8121eef7>] ? __vfs_read+0xa7/0xd0
[176611.094266]  [<ffffffff81066298>] __do_page_fault+0x1a8/0x520
[176611.094280]  [<ffffffff81066632>] do_page_fault+0x22/0x30
[176611.094295]  [<ffffffff81759508>] page_fault+0x28/0x30
[176611.094306] Code: 20 05 a1 81 e8 2f d0 fe ff 0f 0b e8 68 ce fe ff 0f 0b 48 89 d6 e8 ee 32 01 00 eb cd 48 c7 c6 b0 2e a1 81 48 89 df e8 0d d0 fe ff <0f> 0b 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 
[176611.094386] RIP  [<ffffffff811dbcb3>] page_move_anon_rmap+0x93/0xa0
[176611.094400]  RSP <ffff8804971e3d58>
[176611.099920] ---[ end trace d9cb6b7ad0bd6c55 ]---
[176611.099922] note: BrowserBlocking[2851] exited with preempt_count 1

I haven't bisected this yet but there seems to be only one commit touching mm in v4.6 so I kind of suspect that it has something to do with the issue. I'll try to revert it next and see if that changes anything.

I've seen the issue now few times but I have no easy means to reproduce it. Only thing that seems to be consistent is the fact that the running process is always chrome.

Quoted 6 lines

The commit in question is:

6d0a07edd17c ("mm: thp: calculate the mapcount correctly for THP pages during WP faults").

Does this ring any bells? Thanks in advance.

Looks like we forgot to align address if the page is huge. I'm not sure if caller or callee should do this.

Below is callee version.

Note that we use address only in CONFIG_DEBUG_VM=y case and the bug is not visible on production kernels with the option disabled.

mm/rmap.c +0 -0

index 8a839935b18c..0ea5d9071b32 100644

Quoted 12 lines

mm/rmap.c +2 -0

index 8a839935b18c..0ea5d9071b32 100644
@@ -1098,6 +1098,8 @@ void page_move_anon_rmap(struct page *page,
 
 	VM_BUG_ON_PAGE(!PageLocked(page), page);
 	VM_BUG_ON_VMA(!anon_vma, vma);
+	if (IS_ENABLED(CONFIG_DEBUG_VM) && PageTransHuge(page))
+		address &= HPAGE_PMD_MASK;
 	VM_BUG_ON_PAGE(page->index != linear_page_index(vma, address), page);
 

mm/rmap.c void page_move_anon_rmap(struct page *page, · line 1105

Quoted 1 line

mm/rmap.c +0 -0

 	anon_vma = (void *) anon_vma + PAGE_MAPPING_ANON;

Reviewed-by Andrea Arcangeli <[email protected]>

Hi,

After upgrading kernel of my desktop system from v4.6-rc7 to v4.6, I've started seeing following:

[176611.093747] page:ffffea0000360000 count:1 mapcount:0 mapping:ffff880034d2e0a1 index:0x1f9b06600 compound_mapcount: 0
[176611.093751] flags: 0x3fff8000044079(locked|uptodate|dirty|lru|active|head|swapbacked)
[176611.093752] page dumped because: VM_BUG_ON_PAGE(page->index != linear_page_index(vma, address))
[176611.093753] page->mem_cgroup:ffff88049e81b800
[176611.093765] ------------[ cut here ]------------

From 4db87e3e44837a0b038e58eaa3fea29db84723ec Mon Sep 17 00:00:00 2001

Quoted 10 lines · Mika Westerberg

Hi,

After upgrading kernel of my desktop system from v4.6-rc7 to v4.6, I've started seeing following:

[176611.093747] page:ffffea0000360000 count:1 mapcount:0 mapping:ffff880034d2e0a1 index:0x1f9b06600 compound_mapcount: 0
[176611.093751] flags: 0x3fff8000044079(locked|uptodate|dirty|lru|active|head|swapbacked)
[176611.093752] page dumped because: VM_BUG_ON_PAGE(page->index != linear_page_index(vma, address))
[176611.093753] page->mem_cgroup:ffff88049e81b800
[176611.093765] ------------[ cut here ]------------

This is a splitted pmd tail that is triggering a COW, but it's still a compound page because the physical split didn't happen yet.

So like Kirill correctly pointed out, in such case we've to do compound_head because the page->mapping that has to be refiled to the local anon_vma is in the head.

It's just a false positive VM_BUG_ON, the code itself is correct.

Production kernels should be built with CONFIG_DEBUG_VM=n so this is not going to affect them and there's no bug for the production builds.

Can you test this to shut off the false positive?

Hmm, the kernel shipped with Fedora 23 has that enabled:

lahna % grep CONFIG_DEBUG_VM /boot/config-4.4.9-300.fc23.x86_64 CONFIG_DEBUG_VM=y
# CONFIG_DEBUG_VM_VMACACHE is not set
# CONFIG_DEBUG_VM_RB is not set

Quoted 6 lines · Mika Westerberg

Hmm, the kernel shipped with Fedora 23 has that enabled:

lahna % grep CONFIG_DEBUG_VM /boot/config-4.4.9-300.fc23.x86_64 CONFIG_DEBUG_VM=y
# CONFIG_DEBUG_VM_VMACACHE is not set
# CONFIG_DEBUG_VM_RB is not set

Yes, it would have been more accurate to say "enterprise", not just "production".

It's great to run Fedora with CONFIG_DEBUG_VM=y and I'd recommend to keep it that way, so it contributes to stronger runtime validation of the VM invariants.

I keep CONFIG_DEBUG_VM=y on all my systems too of course.

Also note the RHEL debug kernel has CONFIG_DEBUG_VM=y also enabled, but only the debug kernel.

In general while testing new kernels with new VM modifications it's good idea to set CONFIG_DEBUG_VM=y, if you can afford the occasional false positive like in this case and it's not an enterprise production kernel, where clearly all testing should have already happened before that become "enterprise" ready in the first place, so we can save a few cycles.

Lately we got VM_WARN_ON too and I added to my tree recently:

(quoted diff) +7 -0

+#define VM_WARN_ON_PAGE(cond, page) \
+       do { \
+               if (unlikely(cond)) { \
+                       dump_page(page, "VM_WARN_ON_PAGE(" __stringify(cond)")");\
+                       __WARN(); \
+               } \
+       } while (0)

So we could convert some... to reduce the pain of a false positive, but in cases like the one that triggered I'm not sure it'd be good idea to switch it to a WARN_ON as it may be a sign of memory corruption if the assert fails (after the patch) and keeping going after memory corruption can actually do more harm than good.

One thing to keep =n however is CONFIG_DEBUG_VM_RB=n, that one is expensive and that's why it has its own separate knob to be able to disable it while keeping CONFIG_DEBUG_VM=y. IIRC I kept originally under #if 0... so I wouldn't recommend to enable VM_RB on production (it's too much overhead), that's a nice validation but for development only.