Re: [linus:master] [mm/vmalloc] a061578043: BUG:spinlock_trylock_failure_on_UP_on_CPU

Vishal Moola (Oracle)
2025-12-11T20:52:51Z

On Thu, Dec 11, 2025 at 09:40:07PM +0800, Oliver Sang wrote:
> hi, Uladzislau Rezki,
>
> On Thu, Dec 11, 2025 at 11:09:43AM +0100, Uladzislau Rezki wrote:
> > On Wed, Dec 10, 2025 at 03:30:51PM -0800, Vishal Moola (Oracle) wrote:
> > > On Wed, Dec 10, 2025 at 02:10:28PM +0800, kernel test robot wrote:
> > > >
> > > >
> > > > Hello,
> > > >
> > > > kernel test robot noticed "BUG:spinlock_trylock_failure_on_UP_on_CPU" on:
> > > >
> > > > commit: a0615780439938e8e61343f1f92a4c54a71dc6a5 ("mm/vmalloc: request large order pages from buddy allocator")
> > > > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> > > >
> > > > [test failed on linus/master cb015814f8b6eebcbb8e46e111d108892c5e6821]
> > > > [test failed on linux-next/master c75caf76ed86bbc15a72808f48f8df1608a0886c]
> > > >
> > > > in testcase: trinity
> > > > version:
> > > > with following parameters:
> > > >
> > > > runtime: 300s
> > > > group: group-03
> > > > nr_groups: 5
> > > >
> > > >
> > > >
> > > > config: x86_64-randconfig-011-20251207
> > > > compiler: clang-20
> > > > test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 32G
> > > >
> > > > (please refer to attached dmesg/kmsg for entire log/backtrace)
> > > >
> > > >
> > > > the issue show randomly (~50%) in tests.
> > > >
> > > > 645a3c4243473d5c a0615780439938e8e61343f1f92
> > > > ---------------- ---------------------------
> > > > fail:runs %reproduction fail:runs
> > > > | | |
> > > > :60 50% 29:60 dmesg.BUG:spinlock_trylock_failure_on_UP_on_CPU
> > > > :60 50% 29:60 dmesg.RIP:_raw_spin_unlock_irqrestore
> > > >
> > > >
> > > >
> > > > If you fix the issue in a separate patch/commit (i.e. not just a new version of
> > > > the same patch/commit), kindly add following tags
> > > > | Reported-by: kernel test robot <oliver.sang@intel.com>
> > > > | Closes: https://lore.kernel.org/oe-lkp/202512101320.e2f2dd6f-lkp@intel.com
> > > >
> > > >
> > > > [ 1046.632156][ C0] BUG: spinlock trylock failure on UP on CPU#0, kcompactd0/28
> > > > [ 1046.633368][ C0] lock: 0xffff888807e35ef0, .magic: dead4ead, .owner: kcompactd0/28, .owner_cpu: 0
> > > > [ 1046.634872][ C0] CPU: 0 UID: 0 PID: 28 Comm: kcompactd0 Not tainted 6.18.0-rc5-00127-ga06157804399 #1 PREEMPT 8cc09ef94dcec767faa911515ce9e609c45db470
> > > > [ 1046.637019][ C0] Call Trace:
> > > > [ 1046.637563][ C0] <IRQ>
> > > > [ 1046.638038][ C0] __dump_stack (lib/dump_stack.c:95)
> > > > [ 1046.638781][ C0] dump_stack_lvl (lib/dump_stack.c:123)
> > > > [ 1046.639512][ C0] dump_stack (lib/dump_stack.c:130)
> > > > [ 1046.640168][ C0] spin_dump (kernel/locking/spinlock_debug.c:71)
> > > > [ 1046.640853][ C0] do_raw_spin_trylock (kernel/locking/spinlock_debug.c:?)
> > > > [ 1046.641678][ C0] _raw_spin_trylock (include/linux/spinlock_api_smp.h:89 kernel/locking/spinlock.c:138)
> > > > [ 1046.642473][ C0] __free_frozen_pages (mm/page_alloc.c:2973)
> > > > [ 1046.643279][ C0] ___free_pages (mm/page_alloc.c:5295)
> > > > [ 1046.643956][ C0] __free_pages (mm/page_alloc.c:5334)
> > > > [ 1046.644624][ C0] tlb_remove_table_rcu (include/linux/mm.h:? include/linux/mm.h:3122 include/asm-generic/tlb.h:220 mm/mmu_gather.c:227 mm/mmu_gather.c:290)
> > > > [ 1046.645520][ C0] ? __cfi_tlb_remove_table_rcu (mm/mmu_gather.c:289)
> > > > [ 1046.646384][ C0] ? rcu_core (kernel/rcu/tree.c:?)
> > > > [ 1046.647092][ C0] rcu_core (include/linux/rcupdate.h:341 kernel/rcu/tree.c:2607 kernel/rcu/tree.c:2861)
> > > > [ 1046.647774][ C0] rcu_core_si (kernel/rcu/tree.c:2879)
> > > > [ 1046.648439][ C0] handle_softirqs (arch/x86/include/asm/jump_label.h:36 include/trace/events/irq.h:142 kernel/softirq.c:623)
> > > > [ 1046.649202][ C0] __irq_exit_rcu (arch/x86/include/asm/jump_label.h:36 kernel/softirq.c:725)
> > > > [ 1046.649919][ C0] irq_exit_rcu (kernel/softirq.c:741)
> > > > [ 1046.650593][ C0] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1052)
> > > > [ 1046.651520][ C0] </IRQ>
> > > > [ 1046.651984][ C0] <TASK>
> > > > [ 1046.652466][ C0] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:697)
> > > > [ 1046.653389][ C0] RIP: 0010:_raw_spin_unlock_irqrestore (arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:152 kernel/locking/spinlock.c:194)
> > > > [ 1046.654391][ C0] Code: 00 44 89 f6 c1 ee 09 48 c7 c7 e0 f2 7e 86 31 d2 31 c9 e8 e8 dd 80 fd 4d 85 f6 74 05 e8 de e5 fd ff 0f ba e3 09 73 01 fb 31 f6 <ff> 0d 2f dc 6f 01 0f 95 c3 40 0f 94 c6 48 c7 c7 10 f3 7e 86 31 d2
> > > > All code
> > > > ========
> > > > 0: 00 44 89 f6 add %al,-0xa(%rcx,%rcx,4)
> > > > 4: c1 ee 09 shr $0x9,%esi
> > > > 7: 48 c7 c7 e0 f2 7e 86 mov $0xffffffff867ef2e0,%rdi
> > > > e: 31 d2 xor %edx,%edx
> > > > 10: 31 c9 xor %ecx,%ecx
> > > > 12: e8 e8 dd 80 fd call 0xfffffffffd80ddff
> > > > 17: 4d 85 f6 test %r14,%r14
> > > > 1a: 74 05 je 0x21
> > > > 1c: e8 de e5 fd ff call 0xfffffffffffde5ff
> > > > 21: 0f ba e3 09 bt $0x9,%ebx
> > > > 25: 73 01 jae 0x28
> > > > 27: fb sti
> > > > 28: 31 f6 xor %esi,%esi
> > > > 2a:* ff 0d 2f dc 6f 01 decl 0x16fdc2f(%rip) # 0x16fdc5f <-- trapping instruction
> > > > 30: 0f 95 c3 setne %bl
> > > > 33: 40 0f 94 c6 sete %sil
> > > > 37: 48 c7 c7 10 f3 7e 86 mov $0xffffffff867ef310,%rdi
> > > > 3e: 31 d2 xor %edx,%edx
> > > >
> > > > Code starting with the faulting instruction
> > > > ===========================================
> > > > 0: ff 0d 2f dc 6f 01 decl 0x16fdc2f(%rip) # 0x16fdc35
> > > > 6: 0f 95 c3 setne %bl
> > > > 9: 40 0f 94 c6 sete %sil
> > > > d: 48 c7 c7 10 f3 7e 86 mov $0xffffffff867ef310,%rdi
> > > > 14: 31 d2 xor %edx,%edx
> > > > [ 1046.657511][ C0] RSP: 0000:ffffc900001cfb50 EFLAGS: 00000246
> > > > [ 1046.658482][ C0] RAX: 0000000000000000 RBX: 0000000000000206 RCX: 0000000000000000
> > > > [ 1046.659740][ C0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> > > > [ 1046.660979][ C0] RBP: ffffc900001cfb68 R08: 0000000000000000 R09: 0000000000000000
> > > > [ 1046.662239][ C0] R10: 0000000000000000 R11: 0000000000000000 R12: ffff888807e35f50
> > > > [ 1046.663505][ C0] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> > > > [ 1046.664741][ C0] free_pcppages_bulk (mm/page_alloc.c:1494)
> > > > [ 1046.665618][ C0] drain_pages_zone (include/linux/spinlock.h:391 mm/page_alloc.c:2632)
> > > > [ 1046.666374][ C0] __drain_all_pages (mm/page_alloc.c:2731)
> > > > [ 1046.667171][ C0] drain_all_pages (mm/page_alloc.c:2747)
> > > > [ 1046.667908][ C0] kcompactd (mm/compaction.c:3115)
> > > > [ 1046.668625][ C0] kthread (kernel/kthread.c:465)
> > > > [ 1046.669299][ C0] ? __cfi_kcompactd (mm/compaction.c:3166)
> > > > [ 1046.670046][ C0] ? __cfi_kthread (kernel/kthread.c:412)
> > > > [ 1046.670764][ C0] ret_from_fork (arch/x86/kernel/process.c:164)
> > > > [ 1046.671483][ C0] ? __cfi_kthread (kernel/kthread.c:412)
> > > > [ 1046.672174][ C0] ret_from_fork_asm (arch/x86/entry/entry_64.S:255)
> > > > [ 1046.672936][ C0] </TASK>
> > > >
> > > >
> > > >
> > > > The kernel config and materials to reproduce are available at:
> > > > https://download.01.org/0day-ci/archive/20251210/202512101320.e2f2dd6f-lkp@intel.com
> > > >
> > >
> > > Hmmm. This looks like a race condition tied to reclaim. I'm assuming
> > > we fail to allocate a page and kick off kswapd. Then when we fall back
> > > to the bulk allocator which tries to remove a pcp page at the same time as
> > > kswapd tries to reclaim it. Maybe?
> > >
> > > Does something like this fix it?
>
> below patch is failed to applied upon a061578043.
>
> since before reporting, we also tested on latest mainline tip at that time:
> [test failed on linus/master cb015814f8b6eebcbb8e46e111d108892c5e6821]
> which still can reproduce the issue, we applied below patch upon this commit.
>
>
> we found the issue still exists, though the rate seems drop, we only reproduced
> the issue 4 times out of 100 runs.
>
> one dmesg attached FYI.
>
>
> [ 448.229620][ C0] BUG: spinlock trylock failure on UP on CPU#0, kcompactd0/28
> [ 448.230037][ C0] lock: 0xffff888807e75f08, .magic: dead4ead, .owner: kcompactd0/28, .owner_cpu: 0
> [ 448.230474][ C0] CPU: 0 UID: 0 PID: 28 Comm: kcompactd0 Not tainted 6.18.0-12693-g5c827f68ce27 #1 PREEMPT b3721ff206516c93c37a896ae4d3df039c2d04c2
> [ 448.231106][ C0] Call Trace:
> [ 448.231264][ C0] <IRQ>
> [ 448.231403][ C0] __dump_stack+0x19/0x40
> [ 448.231627][ C0] dump_stack_lvl+0x36/0xb8
> [ 448.231842][ C0] dump_stack+0x10/0x38
> [ 448.232101][ C0] spin_dump+0x11c/0x1c0
> [ 448.232404][ C0] do_raw_spin_trylock+0xe4/0x138
> [ 448.232758][ C0] _raw_spin_trylock+0x1a/0xb8
> [ 448.233104][ C0] __free_frozen_pages+0x750/0xa80
> [ 448.233456][ C0] ___free_pages+0x67/0x140
> [ 448.233765][ C0] __free_pages+0x10/0x38
> [ 448.234066][ C0] __tlb_remove_table+0x16a/0x200
> [ 448.234412][ C0] tlb_remove_table_rcu+0x77/0xf8
> [ 448.234771][ C0] ? __cfi_tlb_remove_table_rcu+0x8/0x8
> [ 448.235153][ C0] ? rcu_core+0x8af/0x1740
> [ 448.235456][ C0] rcu_core+0xa25/0x1740
> [ 448.235751][ C0] rcu_core_si+0xe/0x38
> [ 448.236038][ C0] handle_softirqs+0x1db/0x700
> [ 448.236371][ C0] __irq_exit_rcu+0x44/0xc0
> [ 448.236678][ C0] irq_exit_rcu+0xe/0x38
> [ 448.236968][ C0] sysvec_apic_timer_interrupt+0x78/0xb8
> [ 448.237382][ C0] </IRQ>
> [ 448.237588][ C0] <TASK>
> [ 448.237798][ C0] asm_sysvec_apic_timer_interrupt+0x1b/0x40
> [ 448.238214][ C0] RIP: 0010:_raw_spin_unlock_irqrestore+0x6b/0xb8
> [ 448.238575][ C0] Code: 00 44 89 f6 c1 ee 09 48 c7 c7 60 91 80 86 31 d2 31 c9 e8 e8 b4 86 fd 4d 85 f6 74 05 e8 9e e9 fd ff 0f ba e3 09 73 01 fb 31 f6 <ff> 0d ef b8 75 01 0f 95 c3 40 0f 94 c6 48 c7 c7 90 91 80 86 31 d2
> [ 448.239787][ C0] RSP: 0000:ffffc900001cfb48 EFLAGS: 00000246
> [ 448.240187][ C0] RAX: 0000000000000000 RBX: 0000000000000206 RCX: 0000000000000000
> [ 448.240700][ C0] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [ 448.241230][ C0] RBP: ffffc900001cfb60 R08: 0000000000000000 R09: 0000000000000000
> [ 448.241758][ C0] R10: 0000000000000000 R11: 0000000000000000 R12: ffff888807e75fc8
> [ 448.242289][ C0] R13: 0000000000000006 R14: 0000000000000000 R15: ffffea000cee6410
> [ 448.242840][ C0] ? _raw_spin_unlock_irqrestore+0x58/0xb8
> [ 448.243241][ C0] free_pcppages_bulk+0x4a2/0x500
> [ 448.243591][ C0] drain_pages_zone+0xa5/0x140
> [ 448.243936][ C0] __drain_all_pages+0x1ab/0x240
> [ 448.244277][ C0] drain_all_pages+0x10/0x38
> [ 448.244587][ C0] kcompactd+0x61f/0xaf8
> [ 448.244900][ C0] kthread+0x586/0x678
> [ 448.245183][ C0] ? __cfi_kcompactd+0x8/0x8
> [ 448.245504][ C0] ? __cfi_kthread+0x8/0x8
> [ 448.245815][ C0] ret_from_fork+0x24a/0x478
> [ 448.246138][ C0] ? __cfi_kthread+0x8/0x8
> [ 448.246453][ C0] ret_from_fork_asm+0x11/0x40
> [ 448.246795][ C0] </TASK>
> [ 693.283069][ T328] hwclock: can't open '/dev/misc/rtc': No such file or directory
> LKP: ttyS0: 289: LKP: tbox cant kexec and rebooting forcely
> [ 701.346273][ T289] sysrq: Emergency Sync
> [ 701.346778][ T10] Emergency Sync complete
> [ 701.347270][ T289] sysrq: Resetting
>
>
> > >
> > > diff --git a/mm/vmalloc.c b/mm/vmalloc.c
> > > index ecbac900c35f..0d1480723ddc 100644
> > > --- a/mm/vmalloc.c
> > > +++ b/mm/vmalloc.c
> > > @@ -3634,7 +3634,7 @@ vm_area_alloc_pages(gfp_t gfp, int nid,
> > > struct page *page;
> > > int i;
> > > unsigned int large_order = ilog2(nr_remaining);
> > > - gfp_t large_gfp = vmalloc_gfp_adjust(gfp, large_order) & ~__GFP_DIRECT_RECLAIM;
> > > + gfp_t large_gfp = vmalloc_gfp_adjust(gfp, large_order) & ~__GFP_RECLAIM;
> > >
> > > large_order = min(max_attempt_order, large_order);
> > >
> > Some thoughts.
> >
> > That trace is not easy to follow. As for this change, probably it
> > is worth to go with anyway. Because, if we are under a low memory
> > condition, it is quite common for Android devices, we do not want
> > to kick frequently kswapd without good reason. We have a fallback
> > to single page allocator.

Yeah. AFAICT, This trace doesn't seem to point at this patch:

__free_frozen_pages+0x750/0xa80 is:
pcp = pcp_spin_trylock(zone->per_cpu_pageset, UP_flags);
if (pcp) {
if (!free_frozen_page_commit(zone, pcp, page, migratetype,
order, fpi_flags, &UP_flags))
return;
------------> pcp_spin_unlock(pcp, UP_flags);

free_pcppages_bulk+0x4a2/0x500 is:
spin_unlock_irqrestore(&zone->lock, flags);

Seeing how masking off reclaim reduced the occurence from 50% -> 5%,
Maybe its some underlying race condition that is encouraged by the
patch? I'm not sure how often people are kicking of kswapd then
immediately calling the bulk allocator...