Hi All,
just noticed a boot splat that probably was there for lone time:
[ 1.118691] ftrace: allocating 50546 entries in 198 pages
[ 1.129690] ftrace: allocated 198 pages with 4 groups
[ 1.130156]
[ 1.130158] =============================
[ 1.130159] [ BUG: Invalid wait context ]
[ 1.130161] 6.7.0-rc3-00837-g403f3e8fda60 #5272 Not tainted
[ 1.130163] -----------------------------
[ 1.130165] swapper/0 is trying to lock:
[ 1.130166] ffff88823fffb1d8 (&zone->lock){....}-{3:3}, at:
__rmqueue_pcplist+0xe80/0x1100
[ 1.130181] other info that might help us debug this:
[ 1.130182] context-{5:5}
[ 1.130184] 3 locks held by swapper/0:
[ 1.130185] #0: ffffffff84334888 (slab_mutex){....}-{4:4}, at:
kmem_cache_create_usercopy+0x47/0x270
[ 1.130197] #1: ffffffff8437aad8 (kmemleak_lock){....}-{2:2}, at:
__create_object+0x36/0xa0
[ 1.130207] #2: ffff8881f6c37c18 (&pcp->lock){....}-{3:3}, at:
get_page_from_freelist+0x8be/0x2250
[ 1.130215] stack backtrace:
[ 1.130217] CPU: 0 PID: 0 Comm: swapper Not tainted
6.7.0-rc3-00837-g403f3e8fda60 #5272
[ 1.130221] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
[ 1.130224] Call Trace:
[ 1.130225] <TASK>
[ 1.130228] dump_stack_lvl+0x4a/0x80
[ 1.130234] __lock_acquire+0xd5d/0x34e0
[ 1.130244] ? lockdep_hardirqs_on_prepare+0x220/0x220
[ 1.130248] ? __lock_acquire+0x906/0x34e0
[ 1.130254] lock_acquire+0x155/0x3b0
[ 1.130258] ? __rmqueue_pcplist+0xe80/0x1100
[ 1.130263] ? lock_sync+0x100/0x100
[ 1.130268] ? secondary_startup_64_no_verify+0x166/0x16b
[ 1.130274] ? lockdep_hardirqs_on_prepare+0x220/0x220
[ 1.130279] _raw_spin_lock_irqsave+0x3f/0x60
[ 1.130284] ? __rmqueue_pcplist+0xe80/0x1100
[ 1.130288] __rmqueue_pcplist+0xe80/0x1100
[ 1.130293] ? lock_acquire+0x165/0x3b0
[ 1.130300] ? find_suitable_fallback+0xe0/0xe0
[ 1.130306] get_page_from_freelist+0x91c/0x2250
[ 1.130314] ? lock_release+0x219/0x3a0
[ 1.130317] ? __stack_depot_save+0x223/0x450
[ 1.130322] ? reacquire_held_locks+0x270/0x270
[ 1.130328] ? __zone_watermark_ok+0x290/0x290
[ 1.130332] ? prepare_alloc_pages.constprop.0+0x173/0x220
[ 1.130337] __alloc_pages+0x188/0x390
[ 1.130342] ? __alloc_pages_slowpath.constprop.0+0x1380/0x1380
[ 1.130347] ? unwind_next_frame+0x1ee/0xe10
[ 1.130354] ? secondary_startup_64_no_verify+0x166/0x16b
[ 1.130358] ? secondary_startup_64_no_verify+0x166/0x16b
[ 1.130362] ? write_profile+0x220/0x220
[ 1.130366] ? policy_nodemask+0x28/0x190
[ 1.130371] alloc_pages_mpol+0xf0/0x2c0
[ 1.130376] ? mempolicy_in_oom_domain+0x90/0x90
[ 1.130381] ? secondary_startup_64_no_verify+0x166/0x16b
[ 1.130387] __stack_depot_save+0x36f/0x450
[ 1.130393] set_track_prepare+0x79/0xa0
[ 1.130396] ? get_object+0x50/0x50
[ 1.130400] ? kmem_cache_alloc_node+0x222/0x3b0
[ 1.130404] ? __kmem_cache_create+0x167/0x5e0
[ 1.130408] ? kmem_cache_create_usercopy+0x17c/0x270
[ 1.130412] ? kmem_cache_create+0x16/0x20
[ 1.130415] ? sched_init+0xf8/0x780
[ 1.130420] ? start_kernel+0x13c/0x390
[ 1.130425] ? x86_64_start_reservations+0x18/0x30
[ 1.130428] ? x86_64_start_kernel+0xb2/0xc0
[ 1.130431] ? secondary_startup_64_no_verify+0x166/0x16b
[ 1.130436] ? strncpy+0x33/0x60
[ 1.130441] __link_object+0x21c/0x4c0
[ 1.130447] __create_object+0x4e/0xa0
[ 1.130452] kmem_cache_alloc_node+0x222/0x3b0
[ 1.130457] ? calculate_sizes+0x2eb/0x320
[ 1.130462] __kmem_cache_create+0x167/0x5e0
[ 1.130467] kmem_cache_create_usercopy+0x17c/0x270
[ 1.130471] ? cpupri_init+0xe6/0x100
[ 1.130478] kmem_cache_create+0x16/0x20
[ 1.130482] sched_init+0xf8/0x780
[ 1.130486] start_kernel+0x13c/0x390
[ 1.130491] x86_64_start_reservations+0x18/0x30
[ 1.130494] x86_64_start_kernel+0xb2/0xc0
[ 1.130498] secondary_startup_64_no_verify+0x166/0x16b
[ 1.130506] </TASK>
[ 1.133575] Running RCU self tests
Looks to be stackdepot related?
I haven't debugged it yet.
Wondering, is this a known issue?
CONFIG_KASAN=y
CONFIG_KASAN_GENERIC=y
CONFIG_KASAN_OUTLINE=y
# CONFIG_KASAN_INLINE is not set
CONFIG_KASAN_STACK=y
CONFIG_KASAN_VMALLOC=y
# CONFIG_KASAN_MODULE_TEST is not set
CONFIG_HAVE_ARCH_KFENCE=y
CONFIG_KFENCE=y
CONFIG_DEBUG_ATOMIC_SLEEP=y
On Thu, 14 Dec 2023 17:25:46 -0800
Alexei Starovoitov <[email protected]> wrote:
> Hi All,
>
> just noticed a boot splat that probably was there for lone time:
>
> [ 1.118691] ftrace: allocating 50546 entries in 198 pages
> [ 1.129690] ftrace: allocated 198 pages with 4 groups
> [ 1.130156]
> [ 1.130158] =============================
> [ 1.130159] [ BUG: Invalid wait context ]
> [ 1.130161] 6.7.0-rc3-00837-g403f3e8fda60 #5272 Not tainted
> [ 1.130163] -----------------------------
> [ 1.130165] swapper/0 is trying to lock:
> [ 1.130166] ffff88823fffb1d8 (&zone->lock){....}-{3:3}, at:
> __rmqueue_pcplist+0xe80/0x1100
> [ 1.130181] other info that might help us debug this:
> [ 1.130182] context-{5:5}
Can you trigger this with CONFIG_PROVE_RAW_LOCK_NESTING disabled?
If not, then I wouldn't worry about it for now, but this will need to be
addressed when PREEMPT_RT is included.
Basically, a spin_lock() in PREEMPT_RT is converted into a mutex, and most
interrupt handlers and all softirqs are turned into threads. But there's
still cases where spin_lock() can not be used. One is for interrupt
handlers that will not turn into a thread (like the timer interrupt), and
for when a raw_spin_lock is held. You can't have:
raw_spin_lock(rawlock);
spin_lock(spinlock);
order.
But if you can trigger it without the PROVE_RAW_LOCK_NESTING, then it's
something that needs to be addressed today.
-- Steve
> [ 1.130184] 3 locks held by swapper/0:
> [ 1.130185] #0: ffffffff84334888 (slab_mutex){....}-{4:4}, at:
> kmem_cache_create_usercopy+0x47/0x270
> [ 1.130197] #1: ffffffff8437aad8 (kmemleak_lock){....}-{2:2}, at:
> __create_object+0x36/0xa0
> [ 1.130207] #2: ffff8881f6c37c18 (&pcp->lock){....}-{3:3}, at:
> get_page_from_freelist+0x8be/0x2250
> [ 1.130215] stack backtrace:
> [ 1.130217] CPU: 0 PID: 0 Comm: swapper Not tainted
> 6.7.0-rc3-00837-g403f3e8fda60 #5272
> [ 1.130221] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
> [ 1.130224] Call Trace:
> [ 1.130225] <TASK>
> [ 1.130228] dump_stack_lvl+0x4a/0x80
> [ 1.130234] __lock_acquire+0xd5d/0x34e0
> [ 1.130244] ? lockdep_hardirqs_on_prepare+0x220/0x220
> [ 1.130248] ? __lock_acquire+0x906/0x34e0
> [ 1.130254] lock_acquire+0x155/0x3b0
> [ 1.130258] ? __rmqueue_pcplist+0xe80/0x1100
> [ 1.130263] ? lock_sync+0x100/0x100
> [ 1.130268] ? secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130274] ? lockdep_hardirqs_on_prepare+0x220/0x220
> [ 1.130279] _raw_spin_lock_irqsave+0x3f/0x60
> [ 1.130284] ? __rmqueue_pcplist+0xe80/0x1100
> [ 1.130288] __rmqueue_pcplist+0xe80/0x1100
> [ 1.130293] ? lock_acquire+0x165/0x3b0
> [ 1.130300] ? find_suitable_fallback+0xe0/0xe0
> [ 1.130306] get_page_from_freelist+0x91c/0x2250
> [ 1.130314] ? lock_release+0x219/0x3a0
> [ 1.130317] ? __stack_depot_save+0x223/0x450
> [ 1.130322] ? reacquire_held_locks+0x270/0x270
> [ 1.130328] ? __zone_watermark_ok+0x290/0x290
> [ 1.130332] ? prepare_alloc_pages.constprop.0+0x173/0x220
> [ 1.130337] __alloc_pages+0x188/0x390
> [ 1.130342] ? __alloc_pages_slowpath.constprop.0+0x1380/0x1380
> [ 1.130347] ? unwind_next_frame+0x1ee/0xe10
> [ 1.130354] ? secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130358] ? secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130362] ? write_profile+0x220/0x220
> [ 1.130366] ? policy_nodemask+0x28/0x190
> [ 1.130371] alloc_pages_mpol+0xf0/0x2c0
> [ 1.130376] ? mempolicy_in_oom_domain+0x90/0x90
> [ 1.130381] ? secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130387] __stack_depot_save+0x36f/0x450
> [ 1.130393] set_track_prepare+0x79/0xa0
> [ 1.130396] ? get_object+0x50/0x50
> [ 1.130400] ? kmem_cache_alloc_node+0x222/0x3b0
> [ 1.130404] ? __kmem_cache_create+0x167/0x5e0
> [ 1.130408] ? kmem_cache_create_usercopy+0x17c/0x270
> [ 1.130412] ? kmem_cache_create+0x16/0x20
> [ 1.130415] ? sched_init+0xf8/0x780
> [ 1.130420] ? start_kernel+0x13c/0x390
> [ 1.130425] ? x86_64_start_reservations+0x18/0x30
> [ 1.130428] ? x86_64_start_kernel+0xb2/0xc0
> [ 1.130431] ? secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130436] ? strncpy+0x33/0x60
> [ 1.130441] __link_object+0x21c/0x4c0
> [ 1.130447] __create_object+0x4e/0xa0
> [ 1.130452] kmem_cache_alloc_node+0x222/0x3b0
> [ 1.130457] ? calculate_sizes+0x2eb/0x320
> [ 1.130462] __kmem_cache_create+0x167/0x5e0
> [ 1.130467] kmem_cache_create_usercopy+0x17c/0x270
> [ 1.130471] ? cpupri_init+0xe6/0x100
> [ 1.130478] kmem_cache_create+0x16/0x20
> [ 1.130482] sched_init+0xf8/0x780
> [ 1.130486] start_kernel+0x13c/0x390
> [ 1.130491] x86_64_start_reservations+0x18/0x30
> [ 1.130494] x86_64_start_kernel+0xb2/0xc0
> [ 1.130498] secondary_startup_64_no_verify+0x166/0x16b
> [ 1.130506] </TASK>
> [ 1.133575] Running RCU self tests
>
> Looks to be stackdepot related?
>
> I haven't debugged it yet.
> Wondering, is this a known issue?
>
> CONFIG_KASAN=y
> CONFIG_KASAN_GENERIC=y
> CONFIG_KASAN_OUTLINE=y
> # CONFIG_KASAN_INLINE is not set
> CONFIG_KASAN_STACK=y
> CONFIG_KASAN_VMALLOC=y
> # CONFIG_KASAN_MODULE_TEST is not set
> CONFIG_HAVE_ARCH_KFENCE=y
> CONFIG_KFENCE=y
> CONFIG_DEBUG_ATOMIC_SLEEP=y
On Thu, Dec 14, 2023 at 5:45 PM Steven Rostedt <[email protected]> wrote:
>
> On Thu, 14 Dec 2023 17:25:46 -0800
> Alexei Starovoitov <[email protected]> wrote:
>
> > Hi All,
> >
> > just noticed a boot splat that probably was there for lone time:
> >
> > [ 1.118691] ftrace: allocating 50546 entries in 198 pages
> > [ 1.129690] ftrace: allocated 198 pages with 4 groups
> > [ 1.130156]
> > [ 1.130158] =============================
> > [ 1.130159] [ BUG: Invalid wait context ]
> > [ 1.130161] 6.7.0-rc3-00837-g403f3e8fda60 #5272 Not tainted
> > [ 1.130163] -----------------------------
> > [ 1.130165] swapper/0 is trying to lock:
> > [ 1.130166] ffff88823fffb1d8 (&zone->lock){....}-{3:3}, at:
> > __rmqueue_pcplist+0xe80/0x1100
> > [ 1.130181] other info that might help us debug this:
> > [ 1.130182] context-{5:5}
>
> Can you trigger this with CONFIG_PROVE_RAW_LOCK_NESTING disabled?
>
> If not, then I wouldn't worry about it for now, but this will need to be
> addressed when PREEMPT_RT is included.
>
> Basically, a spin_lock() in PREEMPT_RT is converted into a mutex, and most
> interrupt handlers and all softirqs are turned into threads. But there's
> still cases where spin_lock() can not be used. One is for interrupt
> handlers that will not turn into a thread (like the timer interrupt), and
> for when a raw_spin_lock is held. You can't have:
>
> raw_spin_lock(rawlock);
> spin_lock(spinlock);
>
> order.
Thanks for explaining.
It's fine without PROVE_RAW_LOCK_NESTING.