2021-05-16 16:46:32

by kernel test robot

[permalink] [raw]
Subject: [mm/slub] ad36bafb3b: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c



Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: ad36bafb3bcdfdb98ae3516285bbb3ecd51d1597 ("mm/slub: use stackdepot to save stack trace in objects")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master


in testcase: rcuscale
version:
with following parameters:

runtime: 300s
scale_type: tasks



on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+----------------------------------------------------------------------------------+------------+------------+
| | 912f180c1b | ad36bafb3b |
+----------------------------------------------------------------------------------+------------+------------+
| boot_successes | 52 | 0 |
| boot_failures | 0 | 65 |
| BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c | 0 | 65 |
| WARNING:inconsistent_lock_state | 0 | 18 |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage | 0 | 18 |
| RIP:check_preemption_disabled | 0 | 2 |
| RIP:rcu_torture_one_read[rcutorture] | 0 | 6 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 20 |
| RIP:debug_lockdep_rcu_enabled | 0 | 1 |
| RIP:___might_sleep | 0 | 5 |
| RIP:pvclock_clocksource_read | 0 | 4 |
| WARNING:suspicious_RCU_usage | 0 | 9 |
| kernel/sched/core.c:#Illegal_context_switch_in_RCU-bh_read-side_critical_section | 0 | 9 |
| WARNING:possible_irq_lock_inversion_dependency_detected | 0 | 11 |
| RIP:rcu_torture_reader[rcutorture] | 0 | 1 |
| RIP:lock_release | 0 | 2 |
| calltrace:do_softirq | 0 | 4 |
| RIP:preempt_count_add | 0 | 9 |
| RIP:kasan_check_range | 0 | 3 |
| RIP:rcutorture_extend_mask[rcutorture] | 0 | 6 |
| WARNING:HARDIRQ-safe->HARDIRQ-unsafe_lock_order_detected | 0 | 4 |
| calltrace:srcu_invoke_callbacks | 0 | 1 |
| RIP:_raw_spin_unlock_irq | 0 | 1 |
| RIP:finish_task_switch | 0 | 1 |
| RIP:torture_random[torture] | 0 | 5 |
| RIP:rcu_is_watching | 0 | 3 |
| RIP:delay_tsc | 0 | 4 |
| RIP:lock_acquire | 0 | 2 |
| RIP:rcu_read_delay[rcutorture] | 0 | 1 |
| RIP:rcutorture_one_extend[rcutorture] | 0 | 12 |
| RIP:default_idle | 0 | 6 |
| RIP:_raw_spin_unlock_irqrestore | 0 | 2 |
| RIP:__kasan_check_read | 0 | 1 |
| RIP:rcu_read_lock_sched_held | 0 | 4 |
| RIP:__srcu_read_unlock | 0 | 1 |
| RIP:get_state_synchronize_rcu | 0 | 1 |
| RIP:__this_cpu_preempt_check | 0 | 1 |
| RIP:_raw_write_unlock_irq | 0 | 1 |
| RIP:rcu_scale_wait_shutdown[rcuscale] | 0 | 1 |
| RIP:__rcu_read_lock | 0 | 1 |
| RIP:preempt_schedule_irq | 0 | 1 |
| RIP:debug_smp_processor_id | 0 | 1 |
| RIP:get_state_synchronize_srcu | 0 | 1 |
| RIP:rcu_read_lock_held_common | 0 | 1 |
| RIP:__handle_mm_fault | 0 | 1 |
| RIP:finish_fault | 0 | 1 |
+----------------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>


[ 6.384600] BUG: sleeping function called from invalid context at mm/page_alloc.c:5036
[ 6.385429] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 1, name: swapper/0
[ 6.386242] no locks held by swapper/0/1.
[ 6.386669] irq event stamp: 2982
[ 6.387029] hardirqs last enabled at (2981): _raw_spin_unlock_irqrestore (kbuild/src/consumer/include/linux/spinlock_api_smp.h:160 kbuild/src/consumer/kernel/locking/spinlock.c:191)
[ 6.387476] hardirqs last disabled at (2982): __slab_alloc+0x77/0xb0
[ 6.387476] softirqs last enabled at (2840): __do_softirq (kbuild/src/consumer/arch/x86/include/asm/preempt.h:27 kbuild/src/consumer/kernel/softirq.c:403 kbuild/src/consumer/kernel/softirq.c:588)
[ 6.387476] softirqs last disabled at (2831): irq_exit_rcu (kbuild/src/consumer/kernel/softirq.c:433 kbuild/src/consumer/kernel/softirq.c:637 kbuild/src/consumer/kernel/softirq.c:649)
[ 6.387476] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.13.0-rc1-03128-gad36bafb3bcd #1
[ 6.387476] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 6.387476] Call Trace:
[ 6.387476] dump_stack_lvl (kbuild/src/consumer/lib/dump_stack.c:122)
[ 6.387476] ? get_partial_node+0x45/0x530
[ 6.387476] dump_stack (kbuild/src/consumer/lib/dump_stack.c:138)
[ 6.387476] ___might_sleep.cold (kbuild/src/consumer/kernel/sched/core.c:9148)
[ 6.387476] __might_sleep (kbuild/src/consumer/kernel/sched/core.c:9102 (discriminator 14))
[ 6.387476] __alloc_pages (kbuild/src/consumer/include/linux/kernel.h:91 kbuild/src/consumer/mm/page_alloc.c:5036 kbuild/src/consumer/mm/page_alloc.c:5228)
[ 6.387476] ? __alloc_pages_slowpath+0x22e0/0x22e0
[ 6.387476] ? __kernel_text_address (kbuild/src/consumer/kernel/extable.c:105)
[ 6.387476] ? arch_stack_walk (kbuild/src/consumer/arch/x86/kernel/stacktrace.c:27 (discriminator 1))
[ 6.387476] alloc_page_interleave (kbuild/src/consumer/include/linux/instrumented.h:71 kbuild/src/consumer/include/asm-generic/atomic-instrumented.h:27 kbuild/src/consumer/include/linux/jump_label.h:266 kbuild/src/consumer/mm/mempolicy.c:2149)
[ 6.387476] alloc_pages (kbuild/src/consumer/mm/mempolicy.c:2277)
[ 6.387476] ? __kernfs_new_node+0xd5/0x790
[ 6.387476] stack_depot_save (kbuild/src/consumer/lib/stackdepot.c:304)
[ 6.387476] ? __kernfs_new_node+0xd5/0x790
[ 6.387476] save_stack_trace+0x2b/0x30
[ 6.387476] ? __slab_alloc+0x9f/0xb0
[ 6.387476] ? kmem_cache_alloc (kbuild/src/consumer/mm/slub.c:2920 kbuild/src/consumer/mm/slub.c:2962 kbuild/src/consumer/mm/slub.c:2967)
[ 6.387476] ? __kernfs_new_node+0xd5/0x790
[ 6.387476] ? kernfs_new_node (kbuild/src/consumer/fs/kernfs/dir.c:688)
[ 6.387476] ? __kernfs_create_file (kbuild/src/consumer/fs/kernfs/file.c:987)
[ 6.387476] ? sysfs_add_file_mode_ns (kbuild/src/consumer/fs/sysfs/file.c:324)
[ 6.387476] ? sysfs_create_file_ns (kbuild/src/consumer/fs/sysfs/file.c:343)
[ 6.387476] ? bus_create_file (kbuild/src/consumer/drivers/base/bus.c:54 kbuild/src/consumer/drivers/base/bus.c:136)
[ 6.387476] ? bus_register (kbuild/src/consumer/drivers/base/bus.c:567 kbuild/src/consumer/drivers/base/bus.c:835)
[ 6.387476] ? subsys_register (kbuild/src/consumer/drivers/base/bus.c:1087)
[ 6.387476] ? subsys_system_register (kbuild/src/consumer/drivers/base/bus.c:1144)
[ 6.387476] ? cpu_dev_init (kbuild/src/consumer/drivers/base/cpu.c:608)
[ 6.387476] ? driver_init (kbuild/src/consumer/drivers/base/init.c:37)
[ 6.387476] ? kernel_init_freeable (kbuild/src/consumer/init/main.c:1395 kbuild/src/consumer/init/main.c:1600)
[ 6.387476] ? kernel_init (kbuild/src/consumer/init/main.c:1489)
[ 6.387476] ? ret_from_fork (kbuild/src/consumer/arch/x86/entry/entry_64.S:300)
[ 6.387476] set_track (kbuild/src/consumer/mm/slub.c:628)
[ 6.387476] alloc_debug_processing (kbuild/src/consumer/mm/slub.c:1208)
[ 6.387476] ___slab_alloc (kbuild/src/consumer/mm/slub.c:2810)
[ 6.387476] ? __kernfs_new_node+0xd5/0x790
[ 6.387476] ? __slab_alloc+0x77/0xb0
[ 6.387476] ? kmem_cache_alloc (kbuild/src/consumer/mm/slub.c:2920 kbuild/src/consumer/mm/slub.c:2962 kbuild/src/consumer/mm/slub.c:2967)
[ 6.387476] __slab_alloc+0x9f/0xb0
[ 6.387476] ? __kernfs_new_node+0xd5/0x790
[ 6.387476] kmem_cache_alloc (kbuild/src/consumer/mm/slub.c:2920 kbuild/src/consumer/mm/slub.c:2962 kbuild/src/consumer/mm/slub.c:2967)
[ 6.387476] __kernfs_new_node+0xd5/0x790
[ 6.387476] ? kernfs_fop_readdir (kbuild/src/consumer/fs/kernfs/dir.c:612)
[ 6.387476] ? wait_for_completion (kbuild/src/consumer/kernel/locking/mutex.c:1216)
[ 6.387476] ? mutex_unlock (kbuild/src/consumer/kernel/locking/mutex.c:731)
[ 6.387476] ? kernfs_activate (kbuild/src/consumer/fs/kernfs/dir.c:1281)
[ 6.387476] kernfs_new_node (kbuild/src/consumer/fs/kernfs/dir.c:688)
[ 6.387476] __kernfs_create_file (kbuild/src/consumer/fs/kernfs/file.c:987)
[ 6.387476] sysfs_add_file_mode_ns (kbuild/src/consumer/fs/sysfs/file.c:324)
[ 6.387476] ? kfree_const (kbuild/src/consumer/mm/util.c:41)
[ 6.387476] ? kobject_set_name_vargs (kbuild/src/consumer/lib/kobject.c:310)
[ 6.387476] sysfs_create_file_ns (kbuild/src/consumer/fs/sysfs/file.c:343)
[ 6.387476] ? kernfs_get (kbuild/src/consumer/arch/x86/include/asm/atomic.h:95 (discriminator 3) kbuild/src/consumer/include/asm-generic/atomic-instrumented.h:241 (discriminator 3) kbuild/src/consumer/fs/kernfs/dir.c:495 (discriminator 3))
[ 6.387476] ? sysfs_add_file_mode_ns (kbuild/src/consumer/fs/sysfs/file.c:335)
[ 6.387476] bus_create_file (kbuild/src/consumer/drivers/base/bus.c:54 kbuild/src/consumer/drivers/base/bus.c:136)
[ 6.387476] bus_register (kbuild/src/consumer/drivers/base/bus.c:567 kbuild/src/consumer/drivers/base/bus.c:835)
[ 6.387476] subsys_register (kbuild/src/consumer/drivers/base/bus.c:1087)
[ 6.387476] subsys_system_register (kbuild/src/consumer/drivers/base/bus.c:1144)
[ 6.387476] cpu_dev_init (kbuild/src/consumer/drivers/base/cpu.c:608)
[ 6.387476] driver_init (kbuild/src/consumer/drivers/base/init.c:37)
[ 6.387476] kernel_init_freeable (kbuild/src/consumer/init/main.c:1395 kbuild/src/consumer/init/main.c:1600)
[ 6.387476] ? rest_init (kbuild/src/consumer/init/main.c:1484)
[ 6.387476] kernel_init (kbuild/src/consumer/init/main.c:1489)
[ 6.387476] ret_from_fork (kbuild/src/consumer/arch/x86/entry/entry_64.S:300)
[ 6.387900] x86/mm: Memory block size: 128MB
[ 6.449462] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370867519511994 ns
[ 6.450545] futex hash table entries: 512 (order: 4, 65536 bytes, linear)
[ 6.451199] pinctrl core: initialized pinctrl subsystem
[ 6.451763] pinctrl core: failed to create debugfs directory
[ 6.455334] NET: Registered protocol family 16
[ 6.459424] DMA: preallocated 2048 KiB GFP_KERNEL pool for atomic allocations
[ 6.460320] DMA: preallocated 2048 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[ 6.460942] DMA: preallocated 2048 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[ 6.465270] thermal_sys: Registered thermal governor 'user_space'
[ 6.465524] EISA bus registered
[ 6.466657] cpuidle: using governor ladder
[ 6.468049] Callback from call_rcu_tasks_trace() invoked.
[ 6.468804] Callback from call_rcu_tasks_rude() invoked.
[ 6.468800] ACPI: bus type PCI registered
[ 6.469928] PCI: Using configuration type 1 for base access
[ 6.728660] cryptomgr_test (33) used greatest stack depth: 29432 bytes left
[ 6.743101] cryptd: max_cpu_qlen set to 1000
[ 6.817477] raid6: sse2x4 gen() 10916 MB/s
[ 6.817567] Callback from call_rcu_tasks() invoked.
[ 6.873723] raid6: sse2x4 xor() 6327 MB/s
[ 6.930478] raid6: sse2x2 gen() 10395 MB/s
[ 6.987162] raid6: sse2x2 xor() 6272 MB/s
[ 7.043852] raid6: sse2x1 gen() 7328 MB/s
[ 7.100533] raid6: sse2x1 xor() 4848 MB/s
[ 7.100823] raid6: using algorithm sse2x4 gen() 10916 MB/s
[ 7.101406] raid6: .... xor() 6327 MB/s, rmw enabled
[ 7.101929] raid6: using ssse3x2 recovery algorithm
[ 7.104598] ACPI: Added _OSI(Module Device)
[ 7.105060] ACPI: Added _OSI(Processor Device)
[ 7.105551] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 7.106055] ACPI: Added _OSI(Processor Aggregator Device)
[ 7.106650] ACPI: Added _OSI(Linux-Dell-Video)
[ 7.107158] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[ 7.107510] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[ 7.150345] ACPI: 1 ACPI AML tables successfully acquired and loaded
[ 7.191306] ACPI: Interpreter enabled
[ 7.191815] ACPI: (supports S0 S5)
[ 7.192217] ACPI: Using IOAPIC for interrupt routing
[ 7.193064] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 7.197400] ACPI: Enabled 2 GPEs in block 00 to 0F
[ 7.297146] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 7.297538] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3]
[ 7.298754] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[ 7.309773] PCI host bridge to bus 0000:00
[ 7.310281] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 7.310836] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 7.311583] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 7.312415] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
[ 7.313250] pci_bus 0000:00: root bus resource [mem 0x440000000-0x4bfffffff window]
[ 7.314089] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 7.314441] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 7.319375] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 7.324013] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[ 7.327090] pci 0000:00:01.1: reg 0x20: [io 0xc040-0xc04f]
[ 7.328680] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 7.329434] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 7.330128] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 7.330825] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 7.334549] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[ 7.335727] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
[ 7.336504] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
[ 7.340963] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000
[ 7.344104] pci 0000:00:02.0: reg 0x10: [mem 0xfd000000-0xfdffffff pref]
[ 7.346033] pci 0000:00:02.0: reg 0x18: [mem 0xfebf0000-0xfebf0fff]
[ 7.350840] pci 0000:00:02.0: reg 0x30: [mem 0xfebe0000-0xfebeffff pref]
[ 7.355365] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000
[ 7.356835] pci 0000:00:03.0: reg 0x10: [mem 0xfebc0000-0xfebdffff]
[ 7.358250] pci 0000:00:03.0: reg 0x14: [io 0xc000-0xc03f]
[ 7.362520] pci 0000:00:03.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref]
[ 7.367215] pci 0000:00:04.0: [8086:25ab] type 00 class 0x088000
[ 7.367928] pci 0000:00:04.0: reg 0x10: [mem 0xfebf1000-0xfebf100f]


To reproduce:

# build kernel
cd linux
cp config-5.13.0-rc1-03128-gad36bafb3bcd .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation

Thanks,
Oliver Sang


Attachments:
(No filename) (17.78 kB)
config-5.13.0-rc1-03128-gad36bafb3bcd (138.89 kB)
job-script (4.59 kB)
dmesg.xz (27.49 kB)
Download all attachments

2021-05-19 21:08:59

by Andrew Morton

[permalink] [raw]
Subject: Re: [mm/slub] ad36bafb3b: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c

On Sun, 16 May 2021 22:41:52 +0800 kernel test robot <[email protected]> wrote:

> FYI, we noticed the following commit (built with gcc-9):
>
> commit: ad36bafb3bcdfdb98ae3516285bbb3ecd51d1597 ("mm/slub: use stackdepot to save stack trace in objects")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>

I expect
https://lkml.kernel.org/r/[email protected] will
fix this?


2021-05-24 05:27:14

by David Rientjes

[permalink] [raw]
Subject: Re: [mm/slub] ad36bafb3b: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c

On Tue, 18 May 2021, Andrew Morton wrote:

> On Sun, 16 May 2021 22:41:52 +0800 kernel test robot <[email protected]> wrote:
>
> > FYI, we noticed the following commit (built with gcc-9):
> >
> > commit: ad36bafb3bcdfdb98ae3516285bbb3ecd51d1597 ("mm/slub: use stackdepot to save stack trace in objects")
> > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> >
>
> I expect
> https://lkml.kernel.org/r/[email protected] will
> fix this?
>

Yes, that should do it.

2021-06-09 13:59:58

by kernel test robot

[permalink] [raw]
Subject: Re: [mm/slub] ad36bafb3b: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c

hi Andrew,

On Tue, May 18, 2021 at 05:07:00PM -0700, Andrew Morton wrote:
> On Sun, 16 May 2021 22:41:52 +0800 kernel test robot <[email protected]> wrote:
>
> > FYI, we noticed the following commit (built with gcc-9):
> >
> > commit: ad36bafb3bcdfdb98ae3516285bbb3ecd51d1597 ("mm/slub: use stackdepot to save stack trace in objects")
> > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> >
>
> I expect
> https://lkml.kernel.org/r/[email protected] will
> fix this?
>

we tested the patch, and it can fix the issue. thanks