Re: BUG: Bad page map in process init pte:c0ab684c pmd:01182000 (on a PowerMac G4 DP)

On Thu, 29 Feb 2024 17:11:28 +0000
Christophe Leroy [off-list ref] wrote:

Le 29/02/2024 à 02:09, Erhard Furtner a écrit :

quoted

On Mon, 12 Dec 2022 14:31:35 +1000
"Nicholas Piggin" [off-list ref] wrote:
  

quoted

On Thu Dec 1, 2022 at 7:44 AM AEST, Erhard F. wrote:  

quoted

Getting this at boot sometimes, but not always (PowerMac G4 DP, kernel 6.0.9):

[...]
Freeing unused kernel image (initmem) memory: 1328K
Checked W+X mappings: passed, no W+X pages found
rodata_test: all tests were successful
Run /sbin/init as init process
_swap_info_get: Bad swap file entry 24c0ab68
BUG: Bad page map in process init  pte:c0ab684c pmd:01182000  

Have you run memtest on the system? Are the messages related to a
kernel upgrade? This and your KASAN bugs look possibly like random
corruption.

Although with that KASAN one it's strange that kernfs_node_cache
was involved both times, it's strange that page tables are pointing
to that same slab memory. It could be a page table page use-after
-free maybe? Maybe with the page table fragment code. I'm sure other
people would have hit that before though, so I don't know what to
suggest.

Thanks,
Nick  

Revisited the issue on kernel v6.8-rc6 and I can still reproduce it.

Short summary as my last post was over a year ago:
  (x) I get this memory corruption only when CONFIG_VMAP_STACK=y and CONFIG_SMP=y is enabled.
  (x) I don't get this memory corruption when only one of the above is enabled. ^^
  (x) memtester says the 2 GiB RAM in my G4 DP are fine.
  (x) I don't get this issue on my G5 11,2 or Talos II.
  (x) "stress -m 2 --vm-bytes 965M" provokes the issue in < 10 secs. (https://salsa.debian.org/debian/stress)

For the test I used CONFIG_KASAN_INLINE=y for v6.8-rc6 and debug_pagealloc=on, page_owner=on and got this dmesg:

[...]
pagealloc: memory corruption
f5fcfff0: 00 00 00 00                                      ....
CPU: 1 PID: 1788 Comm: stress Tainted: G    B              6.8.0-rc6-PMacG4 #15
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
Call Trace:
[f3bfbac0] [c162a8e8] dump_stack_lvl+0x60/0x94 (unreliable)
[f3bfbae0] [c04edf9c] __kernel_unpoison_pages+0x1e0/0x1f0
[f3bfbb30] [c04a8aa0] post_alloc_hook+0xe0/0x174
[f3bfbb60] [c04a8b58] prep_new_page+0x24/0xbc
[f3bfbb80] [c04abcc4] get_page_from_freelist+0xcd0/0xf10
[f3bfbc50] [c04aecd8] __alloc_pages+0x204/0xe2c
[f3bfbda0] [c04b07a8] __folio_alloc+0x18/0x88
[f3bfbdc0] [c0461a10] vma_alloc_zeroed_movable_folio.isra.0+0x2c/0x6c
[f3bfbde0] [c046bb90] handle_mm_fault+0x91c/0x19ac
[f3bfbec0] [c0047b8c] ___do_page_fault+0x93c/0xc14
[f3bfbf10] [c0048278] do_page_fault+0x28/0x60
[f3bfbf30] [c000433c] DataAccess_virt+0x124/0x17c

--- interrupt: 300 at 0xbe30d8

NIP:  00be30d8 LR: 00be30b4 CTR: 00000000
REGS: f3bfbf40 TRAP: 0300   Tainted: G    B               (6.8.0-rc6-PMacG4)
MSR:  0000d032 <EE,PR,ME,IR,DR,RI>  CR: 20882464  XER: 00000000
DAR: 88c7a010 DSISR: 42000000
GPR00: 00be30b4 af8397d0 a78436c0 6b2ee010 3c500000 20224462 fe77f7e1 00b00264
GPR08: 1d98d000 1d98c000 00000000 40ae256a 20882262 00bffff4 00000000 00000000
GPR16: 00000000 00000002 00000000 0000005a 40802262 80002262 40002262 00c000a4
GPR24: ffffffff ffffffff 3c500000 00000000 00000000 6b2ee010 00c07d64 00001000
NIP [00be30d8] 0xbe30d8
LR [00be30b4] 0xbe30b4

--- interrupt: 300

page:ef4bd92c refcount:1 mapcount:0 mapping:00000000 index:0x1 pfn:0x310b3
flags: 0x80000000(zone=2)
page_type: 0xffffffff()
raw: 80000000 00000100 00000122 00000000 00000001 00000000 ffffffff 00000001
raw: 00000000
page dumped because: pagealloc: corrupted page details
page_owner info is not present (never set?)
swapper/1: page allocation failure: order:0, mode:0x820(GFP_ATOMIC), nodemask=(null),cpuset=/,mems_allowed=0
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G    B              6.8.0-rc6-PMacG4 #15
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
Call Trace:
[f101b9d0] [c162a8e8] dump_stack_lvl+0x60/0x94 (unreliable)
[f101b9f0] [c04ae948] warn_alloc+0x154/0x2e0
[f101bab0] [c04af030] __alloc_pages+0x55c/0xe2c
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)
   cache: skbuff_head_cache, object size: 176, buffer size: 288, default order: 0, min order: 0
   node 0: slabs: 509, objs: 7126, free: 0
[...]

Turned out the "SLUB: Unable to allocate memory on node -1, gfp=0x820(GFP_ATOMIC)" I reported seems a different issue (https://lore.kernel.org/all/20240515224524.1c8befbe@yea/ (local)) not related to the page corruption issue I originally reported in this thread.

The "pagealloc: memory corruption" remains however as of kernel v6.10-rc4.

I reduced and simplified the kernel .config (disabled non-essential drivers, PREEMPT_NONE=y, disabled zswap, disabled lru_gen, etc.) to reduce contributing factors as much as possible. And finally I am getting something meaningful out of KCSAN:

[...] 
BUG: KCSAN: data-race in __hrtimer_run_queues / hrtimer_active

read to 0xeefc7ad0 of 4 bytes by interrupt on cpu 1:
 hrtimer_active+0xb0/0x100
 task_tick_fair+0x7c/0x80
 sched_tick+0x7c/0xd0
 update_process_times+0xc8/0x120
 tick_nohz_handler+0x1ac/0x270
 __hrtimer_run_queues+0x174/0x1dc
 hrtimer_interrupt+0x168/0x350
 timer_interrupt+0x108/0x178
 Decrementer_virt+0x100/0x104
 0xffffffff
 kcsan_setup_watchpoint+0x2dc/0x4a8
 memchr_inv+0x100/0x188
 __kernel_unpoison_pages+0xe0/0x1a8
 post_alloc_hook+0xa4/0x10c
 prep_new_page+0x24/0x5c
 get_page_from_freelist+0x238/0x5e0
 __alloc_pages_noprof+0xec/0x7d0
 __folio_alloc_noprof+0x14/0x30
 vma_alloc_zeroed_movable_folio.isra.0+0x34/0x7c
 handle_mm_fault+0x368/0xd00
 ___do_page_fault+0x3ac/0x504
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

write to 0xeefc7ad0 of 4 bytes by interrupt on cpu 0:
 __hrtimer_run_queues+0x1d0/0x1dc
 hrtimer_interrupt+0x168/0x350
 timer_interrupt+0x108/0x178
 Decrementer_virt+0x100/0x104
 0x67e51595
 mas_start+0x64/0x1b0
 mas_state_walk+0x24/0x78
 mt_find+0xa8/0x20c
 find_vma+0x44/0x68
 lock_mm_and_find_vma+0x44/0x1a8
 ___do_page_fault+0x33c/0x504
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

Reported by Kernel Concurrency Sanitizer on:
CPU: 0 PID: 1452 Comm: stress Not tainted 6.10.0-rc4-PMacG4 #28
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
==================================================================
==================================================================
BUG: KCSAN: data-race in __hrtimer_run_queues / hrtimer_active

read to 0xeefc7ad0 of 4 bytes by interrupt on cpu 1:
 hrtimer_active+0xb0/0x100
 task_tick_fair+0x7c/0x80
 sched_tick+0x7c/0xd0
 update_process_times+0xc8/0x120
 tick_nohz_handler+0x1ac/0x270
 __hrtimer_run_queues+0x174/0x1dc
 hrtimer_interrupt+0x168/0x350
 timer_interrupt+0x108/0x178
 Decrementer_virt+0x100/0x104
 0x0
 kcsan_setup_watchpoint+0x2dc/0x4a8
 memchr_inv+0x100/0x188
 __kernel_unpoison_pages+0xe0/0x1a8
 post_alloc_hook+0xa4/0x10c
 prep_new_page+0x24/0x5c
 get_page_from_freelist+0x238/0x5e0
 __alloc_pages_noprof+0xec/0x7d0
 __folio_alloc_noprof+0x14/0x30
 vma_alloc_zeroed_movable_folio.isra.0+0x34/0x7c
 handle_mm_fault+0x368/0xd00
 ___do_page_fault+0x3ac/0x504
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

write to 0xeefc7ad0 of 4 bytes by interrupt on cpu 0:
 __hrtimer_run_queues+0x1d0/0x1dc
 hrtimer_interrupt+0x168/0x350
 timer_interrupt+0x108/0x178
 Decrementer_virt+0x100/0x104
 memchr_inv+0x100/0x188
 __kernel_unpoison_pages+0xe0/0x1a8
 post_alloc_hook+0xa4/0x10c
 prep_new_page+0x24/0x5c
 get_page_from_freelist+0x238/0x5e0
 __alloc_pages_noprof+0xec/0x7d0
 __folio_alloc_noprof+0x14/0x30
 vma_alloc_zeroed_movable_folio.isra.0+0x34/0x7c
 handle_mm_fault+0x368/0xd00
 ___do_page_fault+0x3ac/0x504
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

Reported by Kernel Concurrency Sanitizer on:
CPU: 0 PID: 1452 Comm: stress Not tainted 6.10.0-rc4-PMacG4 #28
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
==================================================================
pagealloc: memory corruption
fffcfff0: 00 00 00 00                                      ....
CPU: 1 PID: 1453 Comm: stress Not tainted 6.10.0-rc4-PMacG4 #28
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
Call Trace:
[f2f59c60] [c09ba37c] dump_stack_lvl+0x78/0xac (unreliable)
[f2f59c80] [c09ba3d0] dump_stack+0x20/0x34
[f2f59c90] [c02624a8] __kernel_unpoison_pages+0x198/0x1a8
[f2f59ce0] [c0247168] post_alloc_hook+0xa4/0x10c
[f2f59d00] [c02471f4] prep_new_page+0x24/0x5c
[f2f59d20] [c0247c5c] get_page_from_freelist+0x238/0x5e0
[f2f59da0] [c0249720] __alloc_pages_noprof+0xec/0x7d0
[f2f59e40] [c024a39c] __folio_alloc_noprof+0x14/0x30
[f2f59e50] [c0223104] vma_alloc_zeroed_movable_folio.isra.0+0x34/0x7c
[f2f59e70] [c02288f0] handle_mm_fault+0x368/0xd00
[f2f59ef0] [c0031488] ___do_page_fault+0x3ac/0x504
[f2f59f30] [c00317f8] do_page_fault+0x20/0x38
[f2f59f40] [c0004324] DataAccess_virt+0x11c/0x174

--- interrupt: 300 at 0x8c3008

NIP:  008c3008 LR: 008c2fe8 CTR: a78e4a68
REGS: f2f59f50 TRAP: 0300   Not tainted  (6.10.0-rc4-PMacG4)
MSR:  0000d032 <EE,PR,ME,IR,DR,RI>  CR: 20882464  XER: 00000000
DAR: 8f860010 DSISR: 42000000 
GPR00: 008c2fe8 afd8fa70 a7922780 6c2ce010 3b600000 00000000 00000003 007e01e4 
GPR08: 23593000 23592000 00000000 a78e4a68 20882462 008dff68 00000000 40882462 
GPR16: ffffffff 00000000 00000002 00000000 00000001 00000000 008e0018 00000001 
GPR24: ffffffff ffffffff 3b600000 0000005a 6c2ce010 00000000 008e7cd0 00001000 
NIP [008c3008] 0x8c3008
LR [008c2fe8] 0x8c2fe8

--- interrupt: 300

page: refcount:1 mapcount:0 mapping:00000000 index:0x0 pfn:0x3106d
flags: 0x80000000(zone=2)
raw: 80000000 00000100 00000122 00000000 00000000 00000000 ffffffff 00000001
page dumped because: pagealloc: corrupted page details
[...]

'stress' mentioned by KCSAN is the process I use to trigger the page corruption via "stress -m 2 --vm-bytes 950M".

I tried this several times and "BUG: KCSAN: data-race in __hrtimer_run_queues / hrtimer_active" repeatedly shows up in dmesg shortly before the page corruption, though not always. Sometimes I got instead:

[...]
BUG: KCSAN: data-race in alloc_tag_restore / alloc_tag_save

read to 0xc3282278 of 4 bytes by interrupt on cpu 0:
 alloc_tag_save+0x2c/0x64
 __alloc_skb+0x130/0x208
 __netdev_alloc_skb+0x4c/0x2a0
 gem_poll+0x12d4/0x16b8
 __napi_poll.constprop.0+0x64/0x264
 net_rx_action+0x2a4/0x4b8
 handle_softirqs+0x280/0x2fc
 do_softirq_own_stack+0x70/0x90
 do_softirq_own_stack+0x60/0x90
 __irq_exit_rcu+0x88/0x118
 irq_exit+0x10/0x20
 interrupt_async_exit_prepare.isra.0+0x18/0x2c
 do_IRQ+0x24/0x2c
 HardwareInterrupt_virt+0x100/0x104
 folios_put_refs+0xb0/0x1ec
 udelay+0x1c/0x2c
 kcsan_setup_watchpoint+0x2dc/0x4a8
 alloc_tag_restore+0x54/0x78
 folio_alloc_noprof.constprop.0+0x68/0x8c
 vma_alloc_zeroed_movable_folio.isra.0+0x4c/0xac
 handle_mm_fault+0x368/0xd1c
 ___do_page_fault+0x3ac/0x514
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

write to 0xc3282278 of 4 bytes by task 1572 on cpu 0:
 alloc_tag_restore+0x54/0x78
 folio_alloc_noprof.constprop.0+0x68/0x8c
 vma_alloc_zeroed_movable_folio.isra.0+0x4c/0xac
 handle_mm_fault+0x368/0xd1c
 ___do_page_fault+0x3ac/0x514
 do_page_fault+0x20/0x38
 DataAccess_virt+0x11c/0x174

Reported by Kernel Concurrency Sanitizer on:
CPU: 0 PID: 1572 Comm: stress Not tainted 6.10.0-rc4-PMacG4 #23
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
[...]

Full dmesg and kernel .config attached.

Regards,
Erhard