Hello,
kernel test robot noticed "BUG:spinlock_trylock_failure_on_UP_on_CPU" on:
commit: 1d67742f4a90af28c0f655a9ed8d730459b1f220 ("[PATCH v14 6/9] ref_tracker:
automatically register a file in debugfs for a ref_tracker_dir")
url:
https://github.com/intel-lab-lkp/linux/commits/Jeff-Layton/ref_tracker-don-t-use-pK-in-pr_ostream-output/20250610-230236
patch link:
https://lore.kernel.org/all/20250610-reftrack-dbgfs-v14-6-efb532861...@kernel.org/
patch subject: [PATCH v14 6/9] ref_tracker: automatically register a file in
debugfs for a ref_tracker_dir
in testcase: boot
config: i386-randconfig-051-20250611
compiler: clang-20
test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
(please refer to attached dmesg/kmsg for entire log/backtrace)
+---------------------------------------------+------------+------------+
| | ac254e0747 | 1d67742f4a |
+---------------------------------------------+------------+------------+
| BUG:spinlock_trylock_failure_on_UP_on_CPU | 0 | 12 |
| WARNING:at_kernel/workqueue.c:#__queue_work | 0 | 12 |
| EIP:__queue_work | 0 | 12 |
+---------------------------------------------+------------+------------+
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.s...@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202506171517.a1e85b6f-...@intel.com
[ 13.649422][ T1] BUG: spinlock trylock failure on UP on CPU#0, swapper/1
[ 13.650195][ T1] lock: debugfs_dentries+0x0/0x34, .magic: 00000000, .owner:
<none>/-1, .owner_cpu: 0
[ 13.651211][ T1] CPU: 0 UID: 0 PID: 1 Comm: swapper Not tainted
6.15.0-13749-g1d67742f4a90 #1 PREEMPT(undef)
[ 13.652340][ T1] Call Trace:
[ 13.652705][ T1] __dump_stack (lib/dump_stack.c:95)
[ 13.653206][ T1] dump_stack_lvl (lib/dump_stack.c:123)
[ 13.653363][ T1] dump_stack (lib/dump_stack.c:129)
[ 13.653363][ T1] spin_dump (kernel/locking/spinlock_debug.c:71)
[ 13.653363][ T1] do_raw_spin_trylock (kernel/locking/spinlock_debug.c:?)
[ 13.653363][ T1] ? xa_set_mark (lib/xarray.c:2075 lib/xarray.c:2146)
[ 13.653363][ T1] _raw_spin_lock (include/linux/spinlock_api_smp.h:134
kernel/locking/spinlock.c:154)
[ 13.653363][ T1] xa_set_mark (lib/xarray.c:2075 lib/xarray.c:2146)
[ 13.653363][ T1] ref_tracker_dir_exit (include/linux/workqueue.h:723
lib/ref_tracker.c:53 lib/ref_tracker.c:221)
[ 13.653363][ T1] ? kvfree (mm/slub.c:5059)
[ 13.653363][ T1] free_netdev (net/core/dev.c:11880)
[ 13.653363][ T1] free_arcdev (drivers/net/arcnet/arcnet.c:503)
[ 13.653363][ T1] com90io_init (drivers/net/arcnet/com90io.c:401)
[ 13.653363][ T1] do_one_initcall (init/main.c:1273)
[ 13.653363][ T1] ? com90io_setup (drivers/net/arcnet/com90io.c:384)
[ 13.653363][ T1] ? __lock_acquire (kernel/locking/lockdep.c:4677)
[ 13.653363][ T1] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
[ 13.653363][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:271)
[ 13.653363][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.653363][ T1] ? __lock_acquire (kernel/locking/lockdep.c:4677)
[ 13.653363][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.653363][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.653363][ T1] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
[ 13.653363][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:271)
[ 13.653363][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.653363][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.653363][ T1] ? irqtime_account_irq (kernel/sched/cputime.c:?)
[ 13.653363][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.653363][ T1] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4475)
[ 13.653363][ T1] ? trace_hardirqs_on (kernel/trace/trace_preemptirq.c:80)
[ 13.653363][ T1] ? irqentry_exit (kernel/entry/common.c:?)
[ 13.653363][ T1] ? vmware_sched_clock (arch/x86/kernel/apic/apic.c:1050)
[ 13.653363][ T1] ? sysvec_apic_timer_interrupt
(arch/x86/kernel/apic/apic.c:1050)
[ 13.653363][ T1] ? handle_exception (arch/x86/entry/entry_32.S:1048)
[ 13.653363][ T1] ? strlen (arch/x86/lib/string_32.c:?)
[ 13.653363][ T1] ? next_arg (lib/cmdline.c:273)
[ 13.653363][ T1] ? parameq (kernel/params.c:90 kernel/params.c:99)
[ 13.653363][ T1] ? parse_args (kernel/params.c:153)
[ 13.653363][ T1] do_initcall_level (init/main.c:1334)
[ 13.653363][ T1] do_initcalls (init/main.c:1348)
[ 13.653363][ T1] do_basic_setup (init/main.c:1371)
[ 13.653363][ T1] kernel_init_freeable (init/main.c:1585)
[ 13.653363][ T1] ? rest_init (init/main.c:1465)
[ 13.653363][ T1] kernel_init (init/main.c:1475)
[ 13.653363][ T1] ret_from_fork (arch/x86/kernel/process.c:154)
[ 13.653363][ T1] ? debug_smp_processor_id (lib/smp_processor_id.c:60)
[ 13.653363][ T1] ? rest_init (init/main.c:1465)
[ 13.653363][ T1] ret_from_fork_asm (arch/x86/entry/entry_32.S:737)
[ 13.653363][ T1] entry_INT80_32 (arch/x86/entry/entry_32.S:945)
[ 13.679093][ T1] ------------[ cut here ]------------
[ 13.679700][ T1] WARNING: CPU: 0 PID: 1 at kernel/workqueue.c:2325
__queue_work (kernel/workqueue.c:2325)
[ 13.680616][ T1] Modules linked in:
[ 13.681057][ T1] CPU: 0 UID: 0 PID: 1 Comm: swapper Not tainted
6.15.0-13749-g1d67742f4a90 #1 PREEMPT(undef)
[ 13.682176][ T1] EIP: __queue_work (kernel/workqueue.c:2325)
[ 13.682700][ T1] Code: 4d ec 8b 40 04 89 45 f0 31 db 39 c8 0f 95 c3 b8 98 9f
dd d5 89 da 31 c9 6a 00 e8 d4 de 11 00 83 c4 04 8b 45 ec 39 45 f0 74 1a <0f> 0b
b8 b0 9f dd d5 89 da 31 c9 6a 00 e8 b7 de 11 00 83 c4 04 e9
All code
========
0: 4d ec rex.WRB in (%dx),%al
2: 8b 40 04 mov 0x4(%rax),%eax
5: 89 45 f0 mov %eax,-0x10(%rbp)
8: 31 db xor %ebx,%ebx
a: 39 c8 cmp %ecx,%eax
c: 0f 95 c3 setne %bl
f: b8 98 9f dd d5 mov $0xd5dd9f98,%eax
14: 89 da mov %ebx,%edx
16: 31 c9 xor %ecx,%ecx
18: 6a 00 push $0x0
1a: e8 d4 de 11 00 call 0x11def3
1f: 83 c4 04 add $0x4,%esp
22: 8b 45 ec mov -0x14(%rbp),%eax
25: 39 45 f0 cmp %eax,-0x10(%rbp)
28: 74 1a je 0x44
2a:* 0f 0b ud2 <-- trapping instruction
2c: b8 b0 9f dd d5 mov $0xd5dd9fb0,%eax
31: 89 da mov %ebx,%edx
33: 31 c9 xor %ecx,%ecx
35: 6a 00 push $0x0
37: e8 b7 de 11 00 call 0x11def3
3c: 83 c4 04 add $0x4,%esp
3f: e9 .byte 0xe9
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: b8 b0 9f dd d5 mov $0xd5dd9fb0,%eax
7: 89 da mov %ebx,%edx
9: 31 c9 xor %ecx,%ecx
b: 6a 00 push $0x0
d: e8 b7 de 11 00 call 0x11dec9
12: 83 c4 04 add $0x4,%esp
15: e9 .byte 0xe9
[ 13.683052][ T1] EAX: d67dc32c EBX: 00000001 ECX: 00000000 EDX: 00000000
[ 13.683052][ T1] ESI: c0321000 EDI: d576af44 EBP: c03a7b9c ESP: c03a7b7c
[ 13.683052][ T1] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS:
00010017
[ 13.683052][ T1] CR0: 80050033 CR2: b7ded3d5 CR3: 16086000 CR4: 000406d0
[ 13.683052][ T1] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 13.683052][ T1] DR6: fffe0ff0 DR7: 00000400
[ 13.683052][ T1] Call Trace:
[ 13.683052][ T1] queue_work_on (kernel/workqueue.c:2392)
[ 13.683052][ T1] ref_tracker_dir_exit (lib/ref_tracker.c:222)
[ 13.683052][ T1] ? kvfree (mm/slub.c:5059)
[ 13.683052][ T1] free_netdev (net/core/dev.c:11880)
[ 13.683052][ T1] free_arcdev (drivers/net/arcnet/arcnet.c:503)
[ 13.683052][ T1] com90io_init (drivers/net/arcnet/com90io.c:401)
[ 13.683052][ T1] do_one_initcall (init/main.c:1273)
[ 13.683052][ T1] ? com90io_setup (drivers/net/arcnet/com90io.c:384)
[ 13.683052][ T1] ? __lock_acquire (kernel/locking/lockdep.c:4677)
[ 13.683052][ T1] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
[ 13.683052][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:271)
[ 13.683052][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.683052][ T1] ? __lock_acquire (kernel/locking/lockdep.c:4677)
[ 13.683052][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.683052][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.683052][ T1] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
[ 13.683052][ T1] ? sched_clock_noinstr (arch/x86/kernel/tsc.c:271)
[ 13.683052][ T1] ? local_clock_noinstr (kernel/sched/clock.c:269
kernel/sched/clock.c:306)
[ 13.683052][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.683052][ T1] ? irqtime_account_irq (kernel/sched/cputime.c:?)
[ 13.683052][ T1] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67)
[ 13.683052][ T1] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4475)
[ 13.683052][ T1] ? trace_hardirqs_on (kernel/trace/trace_preemptirq.c:80)
[ 13.683052][ T1] ? irqentry_exit (kernel/entry/common.c:?)
[ 13.683052][ T1] ? vmware_sched_clock (arch/x86/kernel/apic/apic.c:1050)
[ 13.683052][ T1] ? sysvec_apic_timer_interrupt
(arch/x86/kernel/apic/apic.c:1050)
[ 13.683052][ T1] ? handle_exception (arch/x86/entry/entry_32.S:1048)
[ 13.683052][ T1] ? strlen (arch/x86/lib/string_32.c:?)
[ 13.683052][ T1] ? next_arg (lib/cmdline.c:273)
[ 13.683052][ T1] ? parameq (kernel/params.c:90 kernel/params.c:99)
[ 13.683052][ T1] ? parse_args (kernel/params.c:153)
[ 13.683052][ T1] do_initcall_level (init/main.c:1334)
[ 13.683052][ T1] do_initcalls (init/main.c:1348)
[ 13.683052][ T1] do_basic_setup (init/main.c:1371)
[ 13.683052][ T1] kernel_init_freeable (init/main.c:1585)
[ 13.683052][ T1] ? rest_init (init/main.c:1465)
[ 13.683052][ T1] kernel_init (init/main.c:1475)
[ 13.683052][ T1] ret_from_fork (arch/x86/kernel/process.c:154)
[ 13.683052][ T1] ? debug_smp_processor_id (lib/smp_processor_id.c:60)
[ 13.683052][ T1] ? rest_init (init/main.c:1465)
[ 13.683052][ T1] ret_from_fork_asm (arch/x86/entry/entry_32.S:737)
[ 13.683052][ T1] entry_INT80_32 (arch/x86/entry/entry_32.S:945)
[ 13.683052][ T1] irq event stamp: 81333
[ 13.683052][ T1] hardirqs last enabled at (81333): _raw_spin_unlock_irqrestore
(arch/x86/include/asm/irqflags.h:19 arch/x86/include/asm/irqflags.h:109
arch/x86/include/asm/irqflags.h:151 include/linux/spinlock_api_smp.h:151
kernel/locking/spinlock.c:194)
[ 13.683052][ T1] hardirqs last disabled at (81332): kvfree_call_rcu
(mm/slab_common.c:1443 mm/slab_common.c:1834 mm/slab_common.c:1963)
[ 13.683052][ T1] softirqs last enabled at (80274): handle_softirqs
(arch/x86/include/asm/preempt.h:27 kernel/softirq.c:426 kernel/softirq.c:607)
[ 13.683052][ T1] softirqs last disabled at (80265): __do_softirq
(kernel/softirq.c:614)
[ 13.683052][ T1] ---[ end trace 0000000000000000 ]---
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250617/202506171517.a1e85b6f-...@intel.com
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
