Re: [PATCH v2 2/3] mm: Split unregister_shrinker() in fast and slow part

From: Yujie Liu
Date: Wed Jun 07 2023 - 03:39:39 EST

On Wed, Jun 07, 2023 at 12:49:55PM +0800, kernel test robot wrote:
>
> Hello,
>
> kernel test robot noticed "INFO:trying_to_register_non-static_key" on:
>
> commit: 107ed33204f77282d67b90f5c37f34c4b1ec9ffb ("[PATCH v2 2/3] mm: Split unregister_shrinker() in fast and slow part")
> url: https://github.com/intel-lab-lkp/linux/commits/Kirill-Tkhai/mm-vmscan-move-shrinker_debugfs_remove-before-synchronize_srcu/20230606-030419
> base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git f8dba31b0a826e691949cd4fdfa5c30defaac8c5
> patch link: https://lore.kernel.org/all/168599179360.70911.4102140966715923751.stgit@xxxxxxx/
> patch subject: [PATCH v2 2/3] mm: Split unregister_shrinker() in fast and slow part
>
> in testcase: boot
>
> compiler: clang-15
> test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
>
> If you fix the issue, kindly add following tag
> | Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
> | Closes: https://lore.kernel.org/oe-lkp/202306071000.4ad4e5ba-oliver.sang@xxxxxxxxx

Sorry the stacktrace in the report was broken due to a toolchain issue
in the bot. Please check the correct stacktrace as below:

[ 0.538549][ T0] INFO: trying to register non-static key.
[ 0.539249][ T0] The code is fine but needs lockdep annotation, or maybe
[ 0.539385][ T0] you didn't initialize this object before use?
[ 0.539385][ T0] turning off the locking correctness validator.
[ 0.539385][ T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.4.0-rc5-00004-g107ed33204f7 #1
[ 0.539385][ T0] Call Trace:
[ 0.539385][ T0] dump_stack_lvl (lib/dump_stack.c:?)
[ 0.539385][ T0] dump_stack (lib/dump_stack.c:113)
[ 0.539385][ T0] assign_lock_key (kernel/locking/lockdep.c:?)
[ 0.539385][ T0] register_lock_class (kernel/locking/lockdep.c:?)
[ 0.539385][ T0] __lock_acquire (kernel/locking/lockdep.c:4965)
[ 0.539385][ T0] ? lock_acquire (kernel/locking/lockdep.c:5705)
[ 0.539385][ T0] ? register_shrinker_prepared (mm/vmscan.c:760)
[ 0.539385][ T0] ? __might_resched (kernel/sched/core.c:10115)
[ 0.539385][ T0] lock_acquire (kernel/locking/lockdep.c:5705)
[ 0.539385][ T0] ? register_shrinker_prepared (mm/vmscan.c:762)
[ 0.539385][ T0] ? __might_resched (kernel/sched/core.c:10115)
[ 0.539385][ T0] down_write (kernel/locking/rwsem.c:1573)
[ 0.539385][ T0] ? register_shrinker_prepared (mm/vmscan.c:762)
[ 0.539385][ T0] register_shrinker_prepared (mm/vmscan.c:762)
[ 0.539385][ T0] sget_fc (fs/super.c:616)
[ 0.539385][ T0] ? kill_litter_super (fs/super.c:1121)
[ 0.539385][ T0] ? shmem_reconfigure (mm/shmem.c:3791)
[ 0.539385][ T0] get_tree_nodev (fs/super.c:1144)
[ 0.539385][ T0] shmem_get_tree (mm/shmem.c:3879)
[ 0.539385][ T0] vfs_get_tree (fs/super.c:1511)
[ 0.539385][ T0] vfs_kern_mount (fs/namespace.c:1036 fs/namespace.c:1065)
[ 0.539385][ T0] kern_mount (fs/namespace.c:4455)
[ 0.539385][ T0] shmem_init (mm/shmem.c:4106)
[ 0.539385][ T0] mnt_init (fs/namespace.c:4440)
[ 0.539385][ T0] vfs_caches_init (fs/dcache.c:3355)
[ 0.539385][ T0] start_kernel (init/main.c:1071)
[ 0.539385][ T0] i386_start_kernel (arch/x86/kernel/head32.c:56)
[ 0.539385][ T0] startup_32_smp (arch/x86/kernel/head_32.S:319)
[ 0.539391][ T0] ------------[ cut here ]------------
[ 0.540097][ T0] DEBUG_RWSEMS_WARN_ON(sem->magic != sem): count = 0x1, magic = 0x0, owner = 0x81d77c00, curr 0x81d77c00, list not empty
[ 0.540405][ T0] WARNING: CPU: 0 PID: 0 at kernel/locking/rwsem.c:1364 up_write (kernel/locking/rwsem.c:1364)
[ 0.541389][ T0] Modules linked in:
[ 0.542390][ T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.4.0-rc5-00004-g107ed33204f7 #1
[ 0.543389][ T0] EIP: up_write (kernel/locking/rwsem.c:1364)
[ 0.543920][ T0] Code: ee 8f c6 81 39 c1 74 05 bb 7f 8b c4 81 53 52 ff 74 24 08 57 ff 74 24 14 68 44 a3 cb 81 68 6d 1a ce 81 e8 32 68 fb ff 83 c4 1c <0f> 0b 39 f7 0f 85 a8 fe ff ff e9 a8 fe ff ff 0f 0b e9 db fe ff ff
All code
========
0: ee out %al,(%dx)
1: 8f c6 pop %rsi
3: 81 39 c1 74 05 bb cmpl $0xbb0574c1,(%rcx)
9: 7f 8b jg 0xffffffffffffff96
b: c4 81 53 52 (bad)
f: ff 74 24 08 push 0x8(%rsp)
13: 57 push %rdi
14: ff 74 24 14 push 0x14(%rsp)
18: 68 44 a3 cb 81 push $0xffffffff81cba344
1d: 68 6d 1a ce 81 push $0xffffffff81ce1a6d
22: e8 32 68 fb ff call 0xfffffffffffb6859
27: 83 c4 1c add $0x1c,%esp
2a:* 0f 0b ud2 <-- trapping instruction
2c: 39 f7 cmp %esi,%edi
2e: 0f 85 a8 fe ff ff jne 0xfffffffffffffedc
34: e9 a8 fe ff ff jmp 0xfffffffffffffee1
39: 0f 0b ud2
3b: e9 db fe ff ff jmp 0xffffffffffffff1b

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 39 f7 cmp %esi,%edi
4: 0f 85 a8 fe ff ff jne 0xfffffffffffffeb2
a: e9 a8 fe ff ff jmp 0xfffffffffffffeb7
f: 0f 0b ud2
11: e9 db fe ff ff jmp 0xfffffffffffffef1
[ 0.544391][ T0] EAX: e6de3575 EBX: 81c48b7f ECX: e6de3575 EDX: 81d67dd0
[ 0.545388][ T0] ESI: 831f4c4c EDI: 00000000 EBP: 81d67ed0 ESP: 81d67ea8
[ 0.546389][ T0] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00210292
[ 0.547388][ T0] CR0: 80050033 CR2: ffd98000 CR3: 02280000 CR4: 00040690
[ 0.548392][ T0] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 0.549388][ T0] DR6: fffe0ff0 DR7: 00000400
[ 0.549947][ T0] Call Trace:
[ 0.550391][ T0] ? show_regs (arch/x86/kernel/dumpstack.c:478)
[ 0.550910][ T0] ? up_write (kernel/locking/rwsem.c:1364)
[ 0.551389][ T0] ? __warn (kernel/panic.c:235 kernel/panic.c:673)
[ 0.551869][ T0] ? up_write (kernel/locking/rwsem.c:1364)
[ 0.552389][ T0] ? up_write (kernel/locking/rwsem.c:1364)
[ 0.552921][ T0] ? report_bug (lib/bug.c:199)
[ 0.553390][ T0] ? exc_overflow (arch/x86/kernel/traps.c:337)
[ 0.554390][ T0] ? handle_bug (arch/x86/kernel/traps.c:324)
[ 0.554923][ T0] ? exc_invalid_op (arch/x86/kernel/traps.c:345)
[ 0.555390][ T0] ? handle_exception (arch/x86/entry/entry_32.S:1076)
[ 0.556022][ T0] ? arch_report_meminfo (arch/x86/mm/pat/set_memory.c:112)
[ 0.556389][ T0] ? exc_overflow (arch/x86/kernel/traps.c:337)
[ 0.557389][ T0] ? up_write (kernel/locking/rwsem.c:1364)
[ 0.557927][ T0] ? exc_overflow (arch/x86/kernel/traps.c:337)
[ 0.558389][ T0] ? up_write (kernel/locking/rwsem.c:1364)
[ 0.558904][ T0] register_shrinker_prepared (mm/vmscan.c:765)
[ 0.559390][ T0] sget_fc (fs/super.c:616)
[ 0.559887][ T0] ? kill_litter_super (fs/super.c:1121)
[ 0.560390][ T0] ? shmem_reconfigure (mm/shmem.c:3791)
[ 0.561390][ T0] get_tree_nodev (fs/super.c:1144)
[ 0.562390][ T0] shmem_get_tree (mm/shmem.c:3879)
[ 0.563390][ T0] vfs_get_tree (fs/super.c:1511)
[ 0.563914][ T0] vfs_kern_mount (fs/namespace.c:1036 fs/namespace.c:1065)
[ 0.564390][ T0] kern_mount (fs/namespace.c:4455)
[ 0.564908][ T0] shmem_init (mm/shmem.c:4106)
[ 0.565389][ T0] mnt_init (fs/namespace.c:4440)
[ 0.565892][ T0] vfs_caches_init (fs/dcache.c:3355)
[ 0.566390][ T0] start_kernel (init/main.c:1071)
[ 0.567390][ T0] i386_start_kernel (arch/x86/kernel/head32.c:56)
[ 0.568009][ T0] startup_32_smp (arch/x86/kernel/head_32.S:319)
[ 0.568392][ T0] irq event stamp: 1613
[ 0.568888][ T0] hardirqs last enabled at (1613): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:42 arch/x86/include/asm/irqflags.h:77 arch/x86/include/asm/irqflags.h:135 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 0.569389][ T0] hardirqs last disabled at (1612): _raw_spin_lock_irqsave (arch/x86/include/asm/preempt.h:80 include/linux/spinlock_api_smp.h:109 kernel/locking/spinlock.c:162)
[ 0.570389][ T0] softirqs last enabled at (1480): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
[ 0.571389][ T0] softirqs last disabled at (1473): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
[ 0.572389][ T0] ---[ end trace 0000000000000000 ]---