FYI, we noticed the following commit (built with gcc-5):
commit: bfa5d8e19798e76de39473b7ecf14f0ce08e8f78 ("hugetlbfs: Convert to fs_context")
https://git.kernel.org/cgit/linux/kernel/git/dhowells/linux-fs.git mount-context
in testcase: boot
on test machine: qemu-system-i386 -enable-kvm -cpu Haswell,+smep,+smap -m 360M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------------------------------------------------------------------+------------+------------+
| | 7c1c3298bf | bfa5d8e197 |
+-------------------------------------------------------------------------------------------------------------+------------+------------+
| boot_successes | 2 | 0 |
| boot_failures | 8 | 12 |
| WARNING:at_arch/x86/mm/dump_pagetables.c:#note_page | 8 | 8 |
| EIP:note_page | 8 | 8 |
| WARNING:possible_recursive_locking_detected | 0 | 12 |
| BUG_hugetlbfs_inode_cache(Not_tainted):Objects_remaining_in_hugetlbfs_inode_cache_on__kmem_cache_shutdown() | 0 | 12 |
| INFO:Slab#objects=#used=#fp=#flags= | 0 | 12 |
| INFO:Object#@offset= | 0 | 12 |
| INFO:Allocated_in_hugetlbfs_alloc_inode_age=#cpu=#pid= | 0 | 12 |
+-------------------------------------------------------------------------------------------------------------+------------+------------+
[ 0.370000] WARNING: possible recursive locking detected
[ 0.370000] 4.16.0-10623-gbfa5d8e #2 Not tainted
[ 0.370000] --------------------------------------------
[ 0.370000] swapper/0/1 is trying to acquire lock:
[ 0.370000] 05b81b35 (&(&n->list_lock)->rlock){..-.}, at: get_partial_node+0x2f/0x31d
[ 0.371016]
[ 0.371016] but task is already holding lock:
[ 0.372147] e4819006 (&(&n->list_lock)->rlock){..-.}, at: __kmem_cache_shutdown+0x61/0x374
[ 0.372150]
[ 0.372150] other info that might help us debug this:
[ 0.372150] Possible unsafe locking scenario:
[ 0.372150]
[ 0.372150] CPU0
[ 0.372150] ----
[ 0.372150] lock(&(&n->list_lock)->rlock);
[ 0.372150] lock(&(&n->list_lock)->rlock);
[ 0.372150]
[ 0.372150] *** DEADLOCK ***
[ 0.372150]
[ 0.372150] May be due to missing lock nesting notation
[ 0.372150]
[ 0.372150] 3 locks held by swapper/0/1:
[ 0.372150] #0: f93bcb55 (cpu_hotplug_lock.rw_sem){.+.+}, at: kmem_cache_destroy+0x14/0xe9
[ 0.372150] #1: b696535c (slab_mutex){+.+.}, at: kmem_cache_destroy+0x20/0xe9
[ 0.372150] #2: e4819006 (&(&n->list_lock)->rlock){..-.}, at: __kmem_cache_shutdown+0x61/0x374
[ 0.372150]
[ 0.372150] stack backtrace:
[ 0.372150] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.16.0-10623-gbfa5d8e #2
[ 0.372150] Call Trace:
[ 0.372150] dump_stack+0x76/0xa9
[ 0.372150] __lock_acquire+0x1040/0x18cb
[ 0.372150] ? ret_from_fork+0x2e/0x38
[ 0.372150] ? __kernel_text_address+0xb/0x2d
[ 0.372150] lock_acquire+0x8e/0xa8
[ 0.372150] ? get_partial_node+0x2f/0x31d
[ 0.372150] _raw_spin_lock+0x3a/0x47
[ 0.372150] ? get_partial_node+0x2f/0x31d
[ 0.372150] get_partial_node+0x2f/0x31d
[ 0.372150] ? mark_held_locks+0x5c/0x7d
[ 0.372150] ? __lock_acquire+0x3fc/0x18cb
[ 0.372150] ___slab_alloc+0xb4/0x422
[ 0.372150] ? __kmem_cache_shutdown+0x137/0x374
[ 0.372150] ? mark_held_locks+0x5c/0x7d
[ 0.372150] ? kfree+0xde/0x143
[ 0.372150] __slab_alloc+0x3b/0x70
[ 0.372150] ? __kmem_cache_shutdown+0x137/0x374
[ 0.372150] __kmalloc+0x16e/0x19c
[ 0.372150] ? __kmem_cache_shutdown+0x137/0x374
[ 0.372150] __kmem_cache_shutdown+0x137/0x374
[ 0.372150] kmem_cache_destroy+0x44/0xe9
[ 0.372150] init_hugetlbfs_fs+0xec/0x11e
[ 0.372150] ? init_ramfs_fs+0x1d/0x1d
[ 0.372150] do_one_initcall+0x41/0x178
[ 0.372150] ? do_early_param+0x73/0x73
[ 0.372150] ? parse_args+0x197/0x2ac
[ 0.372150] kernel_init_freeable+0xeb/0x168
[ 0.372150] ? rest_init+0x1e0/0x1e0
[ 0.372150] kernel_init+0xb/0xe5
[ 0.372150] ? schedule_tail_wrapper+0x9/0xc
[ 0.372150] ret_from_fork+0x2e/0x38
[ 0.372150] =============================================================================
[ 0.372150] BUG hugetlbfs_inode_cache (Not tainted): Objects remaining in hugetlbfs_inode_cache on __kmem_cache_shutdown()
[ 0.372150] -----------------------------------------------------------------------------
[ 0.372150]
[ 0.372150] INFO: Slab 0x5c10301c objects=11 used=1 fp=0x0105b661 flags=0x8100
[ 0.372150] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G B 4.16.0-10623-gbfa5d8e #2
[ 0.372150] Call Trace:
[ 0.372150] dump_stack+0x76/0xa9
[ 0.372150] slab_err+0x7d/0x96
[ 0.372150] ? __kmalloc+0x137/0x19c
[ 0.372150] ? __kmem_cache_shutdown+0x137/0x374
[ 0.372150] __kmem_cache_shutdown+0x15c/0x374
[ 0.372150] kmem_cache_destroy+0x44/0xe9
[ 0.372150] init_hugetlbfs_fs+0xec/0x11e
[ 0.372150] ? init_ramfs_fs+0x1d/0x1d
[ 0.372150] do_one_initcall+0x41/0x178
[ 0.372150] ? do_early_param+0x73/0x73
[ 0.372150] ? parse_args+0x197/0x2ac
[ 0.372150] kernel_init_freeable+0xeb/0x168
[ 0.372150] ? rest_init+0x1e0/0x1e0
[ 0.372150] kernel_init+0xb/0xe5
[ 0.372150] ? schedule_tail_wrapper+0x9/0xc
[ 0.372150] ret_from_fork+0x2e/0x38
[ 0.372150] INFO: Object 0x42b85cdb @offset=1448
[ 0.372150] INFO: Allocated in hugetlbfs_alloc_inode+0x3f/0x61 age=0 cpu=0 pid=1
[ 0.372150] __slab_alloc+0x3b/0x70
[ 0.372150] kmem_cache_alloc+0x110/0x158
[ 0.372150] hugetlbfs_alloc_inode+0x3f/0x61
[ 0.372150] alloc_inode+0x14/0x6e
[ 0.372150] new_inode_pseudo+0xa/0x43
[ 0.372150] new_inode+0x10/0x20
[ 0.372150] hugetlbfs_fill_super+0xcf/0x17d
[ 0.372150] vfs_get_super+0x6f/0x97
[ 0.372150] hugetlbfs_get_tree+0x12/0x14
[ 0.372150] vfs_get_tree+0x37/0x104
[ 0.372150] init_hugetlbfs_fs+0xb3/0x11e
[ 0.372150] do_one_initcall+0x41/0x178
[ 0.372150] kernel_init_freeable+0xeb/0x168
[ 0.372150] kernel_init+0xb/0xe5
[ 0.372150] ret_from_fork+0x2e/0x38
[ 0.422635] kmem_cache_destroy hugetlbfs_inode_cache: Slab cache still has objects
[ 0.423895] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G B 4.16.0-10623-gbfa5d8e #2
[ 0.425042] Call Trace:
[ 0.425407] dump_stack+0x76/0xa9
[ 0.425741] kmem_cache_destroy+0xe4/0xe9
[ 0.426147] init_hugetlbfs_fs+0xec/0x11e
[ 0.426549] ? init_ramfs_fs+0x1d/0x1d
[ 0.426924] do_one_initcall+0x41/0x178
[ 0.427312] ? do_early_param+0x73/0x73
[ 0.427867] ? parse_args+0x197/0x2ac
[ 0.428285] kernel_init_freeable+0xeb/0x168
[ 0.428862] ? rest_init+0x1e0/0x1e0
[ 0.429358] kernel_init+0xb/0xe5
[ 0.429808] ? schedule_tail_wrapper+0x9/0xc
[ 0.430390] ret_from_fork+0x2e/0x38
[ 0.430988] pnp: PnP ACPI init
[ 0.431675] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[ 0.432799] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[ 0.433864] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[ 0.434827] pnp 00:03: [dma 2]
[ 0.435331] pnp 00:03: Plug and Play ACPI device, IDs PNP0700 (active)
[ 0.436536] pnp 00:04: Plug and Play ACPI device, IDs PNP0400 (active)
[ 0.437794] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active)
[ 0.438976] pnp 00:06: Plug and Play ACPI device, IDs PNP0501 (active)
[ 0.441629] pnp: PnP ACPI: found 7 devices
[ 0.478196] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 0.479832] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 0.480991] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 0.482122] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 0.483369] pci_bus 0000:00: resource 7 [mem 0x16800000-0xfebfffff window]
[ 0.484966] NET: Registered protocol family 2
[ 0.486025] tcp_listen_portaddr_hash hash table entries: 256 (order: 1, 10240 bytes)
[ 0.486858] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.487638] TCP bind hash table entries: 4096 (order: 5, 147456 bytes)
[ 0.488419] TCP: Hash tables configured (established 4096 bind 4096)
[ 0.489146] UDP hash table entries: 256 (order: 2, 20480 bytes)
[ 0.489782] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[ 0.490619] NET: Registered protocol family 1
[ 0.521741] RPC: Registered named UNIX socket transport module.
[ 0.522561] RPC: Registered udp transport module.
[ 0.523423] RPC: Registered tcp transport module.
[ 0.524364] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.525515] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.526608] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[ 0.527683] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.528882] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[ 0.530499] PCI: CLS 0 bytes, default 64
[ 0.531494] Unpacking initramfs...
[ 1.040698] kwatchdog (28) used greatest stack depth: 7460 bytes left
[ 1.953317] debug: unmapping init [mem 0xd44a8000-0xd67dffff]
[ 1.965058] Scanning for low memory corruption every 60 seconds
[ 1.966242] cryptomgr_test (30) used greatest stack depth: 7436 bytes left
[ 1.967031] The force parameter has not been set to 1. The Iris poweroff handler will not be installed.
[ 1.967991] NatSemi SCx200 Driver
[ 1.968530] rcu-torture:--- Start of test: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0
[ 1.972891] rcu-torture: Creating rcu_torture_writer task
[ 1.973971] rcu-torture: Creating rcu_torture_fakewriter task
[ 1.975061] rcu-torture: rcu_torture_writer task started
[ 1.975974] rcu-torture: GP expediting controlled from boot/sysfs for rcu.
[ 1.977131] rcu_torture_writer: Testing conditional GPs.
[ 1.978019] rcu_torture_writer: Testing expedited GPs.
[ 1.978887] rcu_torture_writer: Testing asynchronous GPs.
[ 1.979797] rcu_torture_writer: Testing normal GPs.
[ 1.980710] rcu-torture: rcu_torture_fakewriter task started
[ 1.981703] rcu-torture: Creating rcu_torture_fakewriter task
[ 1.983551] rcu-torture: Creating rcu_torture_fakewriter task
[ 1.984658] rcu-torture: rcu_torture_fakewriter task started
[ 1.985678] rcu-torture: Creating rcu_torture_fakewriter task
[ 1.986775] rcu-torture: rcu_torture_fakewriter task started
[ 1.987803] rcu-torture: Creating rcu_torture_reader task
[ 1.988828] rcu-torture: rcu_torture_fakewriter task started
[ 1.989854] rcu-torture: Creating rcu_torture_stats task
[ 1.990936] rcu-torture: rcu_torture_reader task started
[ 1.991908] rcu-torture: Creating torture_shuffle task
[ 1.992924] rcu-torture: rcu_torture_stats task started
[ 1.993869] rcu-torture: Creating torture_stutter task
[ 1.994589] rcu-torture: torture_shuffle task started
[ 1.995157] rcu-torture: Creating rcu_torture_cbflood task
[ 1.995796] rcu-torture: torture_stutter task started
[ 1.998836] Initialise system trusted keyrings
[ 1.999695] Key type blacklist registered
[ 2.000916] rcu-torture: rcu_torture_cbflood task started
[ 2.002043] workingset: timestamp_bits=30 max_order=17 bucket_order=0
[ 2.035256] cryptomgr_test (49) used greatest stack depth: 7160 bytes left
[ 2.040660] Key type asymmetric registered
To reproduce:
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
Thanks,
Xiaolong