Re: [PATCH V2] tracing/timerlat: Hotplug support for the user-space interface

From: kernel test robot
Date: Sun Sep 24 2023 - 10:43:26 EST



Hello,

kernel test robot noticed "WARNING:possible_recursive_locking_detected" on:

commit: d2618f89d9ede5e14fd2eb2d140fff1d31f4948b ("[PATCH V2] tracing/timerlat: Hotplug support for the user-space interface")
url: https://github.com/intel-lab-lkp/linux/commits/Daniel-Bristot-de-Oliveira/tracing-timerlat-Hotplug-support-for-the-user-space-interface/20230920-234738
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 2cf0f715623872823a72e451243bbf555d10d032
patch link: https://lore.kernel.org/all/6b9a5f306e488bc77bf8521faeade420a0adf3e4.1695224204.git.bristot@xxxxxxxxxx/
patch subject: [PATCH V2] tracing/timerlat: Hotplug support for the user-space interface

in testcase: boot

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

(please refer to attached dmesg/kmsg for entire log/backtrace)



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.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202309242253.a3803da4-oliver.sang@xxxxxxxxx


[ 108.795325][ T1] WARNING: possible recursive locking detected
[ 108.796115][ T1] 6.6.0-rc2-00019-gd2618f89d9ed #1 Not tainted
[ 108.796898][ T1] --------------------------------------------
[ 108.797664][ T1] swapper/0/1 is trying to acquire lock:
[ 108.798384][ T1] ffffffff85550630 (cpu_hotplug_lock){++++}-{0:0}, at: __cpuhp_setup_state (kernel/cpu.c:2553)
[ 108.799656][ T1]
[ 108.799656][ T1] but task is already holding lock:
[ 108.800596][ T1] ffffffff85550630 (cpu_hotplug_lock){++++}-{0:0}, at: init_osnoise_tracer (kernel/trace/trace_osnoise.c:3186)
[ 108.801843][ T1]
[ 108.801843][ T1] other info that might help us debug this:
[ 108.802890][ T1] Possible unsafe locking scenario:
[ 108.802890][ T1]
[ 108.803843][ T1] CPU0
[ 108.804266][ T1] ----
[ 108.804685][ T1] lock(cpu_hotplug_lock);
[ 108.805267][ T1] lock(cpu_hotplug_lock);
[ 108.805845][ T1]
[ 108.805845][ T1] *** DEADLOCK ***
[ 108.805845][ T1]
[ 108.806885][ T1] May be due to missing lock nesting notation
[ 108.806885][ T1]
[ 108.807952][ T1] 1 lock held by swapper/0/1:
[ 108.808547][ T1] #0: ffffffff85550630 (cpu_hotplug_lock){++++}-{0:0}, at: init_osnoise_tracer (kernel/trace/trace_osnoise.c:3186)
[ 108.809838][ T1]
[ 108.809838][ T1] stack backtrace:
[ 108.819007][ T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 6.6.0-rc2-00019-gd2618f89d9ed #1
[ 108.821026][ T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 108.823537][ T1] Call Trace:
[ 108.824310][ T1] <TASK>
[ 108.824999][ T1] dump_stack_lvl (lib/dump_stack.c:107 (discriminator 4))
[ 108.826053][ T1] validate_chain (kernel/locking/lockdep.c:3857)
[ 108.827124][ T1] ? __pfx_validate_chain (kernel/locking/lockdep.c:3824)
[ 108.828310][ T1] ? mark_lock (kernel/locking/lockdep.c:4655 (discriminator 3))
[ 108.829327][ T1] __lock_acquire (kernel/locking/lockdep.c:5136)
[ 108.830430][ T1] ? __cpuhp_setup_state (kernel/cpu.c:2553)
[ 108.831632][ T1] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755 kernel/locking/lockdep.c:5718)
[ 108.832576][ T1] ? __cpuhp_setup_state (kernel/cpu.c:2553)
[ 108.833259][ T1] ? __pfx_lock_acquire (kernel/locking/lockdep.c:5721)
[ 108.833944][ T1] ? __pfx___might_resched (kernel/sched/core.c:10142)
[ 108.834708][ T1] ? preempt_latency_start (include/linux/ftrace.h:974 kernel/sched/core.c:5825 kernel/sched/core.c:5822)
[ 108.835443][ T1] ? __pfx_init_osnoise_tracer (kernel/trace/trace_osnoise.c:3162)
[ 108.836185][ T1] cpus_read_lock (include/linux/percpu-rwsem.h:53 kernel/cpu.c:489)
[ 108.836774][ T1] ? __cpuhp_setup_state (kernel/cpu.c:2553)
[ 108.837437][ T1] __cpuhp_setup_state (kernel/cpu.c:2553)
[ 108.838089][ T1] ? __pfx_osnoise_cpu_die (kernel/trace/trace_osnoise.c:2168)
[ 108.839689][ T1] ? __pfx_osnoise_cpu_init (kernel/trace/trace_osnoise.c:2159)
[ 108.840399][ T1] init_osnoise_tracer (kernel/trace/trace_osnoise.c:2180 kernel/trace/trace_osnoise.c:3187)
[ 108.841052][ T1] do_one_initcall (init/main.c:1232)
[ 108.841674][ T1] ? __pfx_do_one_initcall (init/main.c:1223)
[ 108.842388][ T1] do_initcalls (init/main.c:1293 init/main.c:1310)
[ 108.842971][ T1] kernel_init_freeable (init/main.c:1549)
[ 108.843629][ T1] ? __pfx_kernel_init (init/main.c:1429)
[ 108.844265][ T1] kernel_init (init/main.c:1439)
[ 108.844816][ T1] ? __pfx_kernel_init (init/main.c:1429)
[ 108.845440][ T1] ret_from_fork (arch/x86/kernel/process.c:153)
[ 108.846002][ T1] ? __pfx_kernel_init (init/main.c:1429)
[ 108.846634][ T1] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
[ 108.847259][ T1] </TASK>
[ 108.884553][ T1] Loading compiled-in X.509 certificates
[ 109.254386][ T1] kmemleak: Kernel memory leak detector initialized (mem pool available: 13820)
[ 109.254412][ T88] kmemleak: Automatic memory scanning thread started
[ 109.255698][ T1] debug_vm_pgtable: [debug_vm_pgtable ]: Validating architecture page table helpers
[ 112.395476][ T26] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 112.409788][ T1] Sending DHCP requests ., OK
[ 113.402700][ T1] IP-Config: Got DHCP answer from 10.0.2.2, my address is 10.0.2.15
[ 113.403839][ T1] IP-Config: Complete:
[ 113.404411][ T1] device=eth0, hwaddr=52:54:00:12:34:56, ipaddr=10.0.2.15, mask=255.255.255.0, gw=10.0.2.2
[ 113.405811][ T1] host=vm-meta-46, domain=, nis-domain=(none)
[ 113.406763][ T1] bootserver=10.0.2.2, rootserver=10.0.2.2, rootpath=
[ 113.406775][ T1] nameserver0=10.0.2.3
[ 113.420894][ T1] clk: Disabling unused clocks
[ 113.421617][ T1] kunit: disabled
[ 113.437394][ T1] Freeing unused kernel image (initmem) memory: 6728K
[ 113.443061][ T1] Write protecting the kernel read-only data: 69632k
[ 113.445756][ T1] Freeing unused kernel image (rodata/data gap) memory: 400K
[ 113.454231][ T1] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[ 113.455584][ T1] x86/mm: Checking user space page tables
[ 113.456470][ T1] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[ 113.466947][ T1] Run /init as init process
[ 113.467438][ T1] with arguments:
[ 113.467806][ T1] /init
[ 113.468091][ T1] with environment:
[ 113.468441][ T1] HOME=/
[ 113.468746][ T1] TERM=linux
[ 113.469067][ T1] RESULT_ROOT=/result/boot/1/vm-snb/debian-11.1-i386-20220923.cgz/x86_64-randconfig-001-20230921/gcc-12/d2618f89d9ede5e14fd2eb2d140fff1d31f4948b/3
[ 113.470561][ T1] BOOT_IMAGE=/pkg/linux/x86_64-randconfig-001-20230921/gcc-12/d2618f89d9ede5e14fd2eb2d140fff1d31f4948b/vmlinuz-6.6.0-rc2-00019-gd2618f89d9ed
[ 113.471876][ T1] branch=linux-devel/devel-hourly-20230920-182124
[ 113.472519][ T1] job=/lkp/jobs/scheduled/vm-meta-46/boot-1-debian-11.1-i386-20220923.cgz-x86_64-randconfig-001-20230921-d2618f89d9ed-20230921-20850-pprsaz-1.yaml
[ 113.473851][ T1] user=lkp
[ 113.474160][ T1] ARCH=x86_64
[ 113.474497][ T1] kconfig=x86_64-randconfig-001-20230921
[ 113.475072][ T1] commit=d2618f89d9ede5e14fd2eb2d140fff1d31f4948b
[ 113.475699][ T1] nmi_watchdog=panic
[ 113.476119][ T1] vmalloc=256M
[ 113.476449][ T1] max_uptime=600
[ 113.476808][ T1] LKP_SERVER=internal-lkp-server
[ 113.477275][ T1] selinux=0
[ 113.477584][ T1] softlockup_panic=1
[ 113.477978][ T1] prompt_ramdisk=0
[ 113.478354][ T1] vga=normal
[ 113.586654][ T1] systemd[1]: RTC configured in localtime, applying delta of 0 minutes to system time.


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20230924/202309242253.a3803da4-oliver.sang@xxxxxxxxx



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki