[<prev] [next>] [day] [month] [year] [list]
Message-ID: <202503201652.77970721-lkp@intel.com>
Date: Fri, 21 Mar 2025 14:47:21 +0800
From: kernel test robot <oliver.sang@...el.com>
To: Kees Cook <kees@...nel.org>
CC: <oe-lkp@...ts.linux.dev>, <lkp@...el.com>, Nathan Chancellor
<nathan@...nel.org>, <linux-kernel@...r.kernel.org>,
<linux-hardening@...r.kernel.org>, <oliver.sang@...el.com>
Subject: [linux-next:master] [hardening] d70da12453:
WARNING:possible_circular_locking_dependency_detected_trinity-main_is_trying_to_acquire_lock:at:__perf_event_task_sched_out_but_task_is_already_holding_lock:at:raw_spin_rq_lock_nested
hi, Kees Cook and all,
this is not a regression report as we normally do. we just use this report
FYI that a WARNING shows up in our tests. and it seems due to d70da12453,
there are some changes in WARNING detail stat:
16cb16e0d28501f6 d70da12453ac3797e0c54884305
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
20:20 -100% :20 dmesg.WARNING:possible_circular_locking_dependency_detected_trinity-main_is_trying_to_acquire_lock:at:__perf_event_task_sched_out_but_task_is_already_holding_lock:at:__schedule
:20 100% 20:20 dmesg.WARNING:possible_circular_locking_dependency_detected_trinity-main_is_trying_to_acquire_lock:at:__perf_event_task_sched_out_but_task_is_already_holding_lock:at:raw_spin_rq_lock_nested
we also noticed the config has below diff:
--- /pkg/linux/i386-randconfig-053-20250318/clang-20/16cb16e0d28501f6eef7071675f1ffbceea8dd0d/.config 2025-03-19 13:45:13.488528197 +0800
+++ /pkg/linux/i386-randconfig-053-20250318/clang-20/d70da12453ac3797e0c54884305ccc894e8c817b/.config 2025-03-19 13:56:30.211029259 +0800
@@ -4943,6 +4943,7 @@ CONFIG_ZERO_CALL_USED_REGS=y
#
# Bounds checking
#
+CONFIG_FORTIFY_SOURCE=y
CONFIG_HARDENED_USERCOPY=y
CONFIG_HARDENED_USERCOPY_DEFAULT_ON=y
# end of Bounds checking
@@ -5568,12 +5569,8 @@ CONFIG_TIMERLAT_TRACER=y
# CONFIG_FTRACE_SYSCALLS is not set
CONFIG_TRACER_SNAPSHOT=y
CONFIG_TRACER_SNAPSHOT_PER_CPU_SWAP=y
-CONFIG_TRACE_BRANCH_PROFILING=y
-# CONFIG_BRANCH_PROFILE_NONE is not set
+CONFIG_BRANCH_PROFILE_NONE=y
# CONFIG_PROFILE_ANNOTATED_BRANCHES is not set
-CONFIG_PROFILE_ALL_BRANCHES=y
-CONFIG_TRACING_BRANCHES=y
-CONFIG_BRANCH_TRACER=y
# CONFIG_KPROBE_EVENTS is not set
CONFIG_UPROBE_EVENTS=y
CONFIG_BPF_EVENTS=y
Hello,
kernel test robot noticed "WARNING:possible_circular_locking_dependency_detected_trinity-main_is_trying_to_acquire_lock:at:__perf_event_task_sched_out_but_task_is_already_holding_lock:at:raw_spin_rq_lock_nested" on:
commit: d70da12453ac3797e0c54884305ccc894e8c817b ("hardening: Enable i386 FORTIFY_SOURCE on Clang 16+")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
[test failed on linux-next/master c4d4884b67802c41fd67399747165d65c770621a]
in testcase: trinity
version: trinity-i386-abe9de86-1_20230429
with following parameters:
runtime: 300s
group: group-00
nr_groups: 5
config: i386-randconfig-053-20250318
compiler: clang-20
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@...el.com>
| Closes: https://lore.kernel.org/oe-lkp/202503201652.77970721-lkp@intel.com
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250320/202503201652.77970721-lkp@intel.com
[ 34.400683][ T3405]
[ 34.400794][ T3405] ======================================================
[ 34.401106][ T3405] WARNING: possible circular locking dependency detected
[ 34.401419][ T3405] 6.14.0-rc2-00025-gd70da12453ac #1 Tainted: G T
[ 34.401763][ T3405] ------------------------------------------------------
[ 34.402075][ T3405] trinity-main/3405 is trying to acquire lock:
[ 34.402350][ T3405] ec0b2410 (&ctx->lock){....}-{2:2}, at: __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.402759][ T3405]
[ 34.402759][ T3405] but task is already holding lock:
[ 34.403089][ T3405] 828de790 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x61/0xc0
[ 34.403485][ T3405]
[ 34.403485][ T3405] which lock already depends on the new lock.
[ 34.403485][ T3405]
[ 34.403951][ T3405]
[ 34.403951][ T3405] the existing dependency chain (in reverse order) is:
[ 34.404350][ T3405]
[ 34.404350][ T3405] -> #6 (&rq->__lock){-.-.}-{2:2}:
[ 34.404677][ T3405] _raw_spin_lock_nested+0x2f/0x64
[ 34.404930][ T3405] raw_spin_rq_lock_nested+0x61/0xc0
[ 34.405192][ T3405] __task_rq_lock+0x32/0x80
[ 34.405419][ T3405] wake_up_new_task+0x2c/0xe0
[ 34.405654][ T3405] kernel_clone+0x143/0x230
[ 34.405881][ T3405] user_mode_thread+0xa7/0xc0
[ 34.406116][ T3405] rest_init+0x1a/0x168
[ 34.406328][ T3405] start_kernel+0x307/0x364
[ 34.406556][ T3405] i386_start_kernel+0xd3/0xf4
[ 34.406794][ T3405] startup_32_smp+0x151/0x154
[ 34.407028][ T3405]
[ 34.407028][ T3405] -> #5 (&p->pi_lock){-.-.}-{2:2}:
[ 34.407355][ T3405] _raw_spin_lock_irqsave+0x44/0x7c
[ 34.407614][ T3405] try_to_wake_up+0x74/0x470
[ 34.407844][ T3405] wake_up_process+0xf/0x20
[ 34.408071][ T3405] create_worker+0x181/0x1d0
[ 34.408301][ T3405] workqueue_init+0xb8/0x1b4
[ 34.408531][ T3405] kernel_init_freeable+0x3b/0xb8
[ 34.408780][ T3405] kernel_init+0x12/0x11c
[ 34.408998][ T3405] ret_from_fork+0x2c/0x40
[ 34.409223][ T3405] ret_from_fork_asm+0x12/0x18
[ 34.409461][ T3405] restore_all_switch_stack+0x0/0xb5
[ 34.409722][ T3405]
[ 34.409722][ T3405] -> #4 (&pool->lock){-.-.}-{2:2}:
[ 34.410048][ T3405] _raw_spin_lock+0x2a/0x5c
[ 34.410273][ T3405] __queue_work+0x1cf/0x470
[ 34.410500][ T3405] queue_work_on+0x7f/0xb0
[ 34.410723][ T3405] rpm_suspend+0x4ab/0x710
[ 34.410946][ T3405] rpm_idle+0x8d/0x310
[ 34.411153][ T3405] __pm_runtime_idle+0x5f/0xe0
[ 34.411390][ T3405] __device_attach+0xe5/0x140
[ 34.411628][ T3405] device_initial_probe+0xf/0x20
[ 34.411875][ T3405] bus_probe_device+0x78/0xd0
[ 34.412110][ T3405] device_add+0x20e/0x410
[ 34.412331][ T3405] serial_base_port_add+0x10d/0x130
[ 34.412589][ T3405] serial_core_register_port+0xc8/0x830
[ 34.412863][ T3405] serial_ctrl_register_port+0x8/0x10
[ 34.413130][ T3405] uart_add_one_port+0x8/0x10
[ 34.413366][ T3405] serial8250_register_8250_port+0x69f/0x8d0
[ 34.413659][ T3405] serial_pnp_probe+0x1dd/0x310
[ 34.413902][ T3405] pnp_device_probe+0xb7/0x100
[ 34.414142][ T3405] really_probe+0x174/0x3a0
[ 34.414369][ T3405] __driver_probe_device+0x78/0x170
[ 34.414627][ T3405] driver_probe_device+0x19/0xf0
[ 34.414873][ T3405] __driver_attach+0x8d/0x190
[ 34.415108][ T3405] bus_for_each_dev+0xcc/0xf0
[ 34.415342][ T3405] driver_attach+0x14/0x20
[ 34.415566][ T3405] bus_add_driver+0x140/0x270
[ 34.415805][ T3405] driver_register+0x50/0xd0
[ 34.416036][ T3405] pnp_register_driver+0x19/0x20
[ 34.416282][ T3405] serial8250_pnp_init+0xd/0x10
[ 34.416525][ T3405] serial8250_init+0x69/0xec
[ 34.416757][ T3405] do_one_initcall+0xb4/0x2d0
[ 34.416993][ T3405] do_initcall_level+0x75/0xac
[ 34.417232][ T3405] do_initcalls+0x49/0x9c
[ 34.417452][ T3405] do_basic_setup+0x12/0x14
[ 34.417680][ T3405] kernel_init_freeable+0x6d/0xb8
[ 34.417930][ T3405] kernel_init+0x12/0x11c
[ 34.418150][ T3405] ret_from_fork+0x2c/0x40
[ 34.418375][ T3405] ret_from_fork_asm+0x12/0x18
[ 34.418614][ T3405] restore_all_switch_stack+0x0/0xb5
[ 34.418877][ T3405]
[ 34.418877][ T3405] -> #3 (&dev->power.lock){-...}-{3:3}:
[ 34.419224][ T3405] _raw_spin_lock_irqsave+0x44/0x7c
[ 34.419480][ T3405] __pm_runtime_resume+0x49/0x70
[ 34.419731][ T3405] __uart_start+0x54/0xd0
[ 34.419953][ T3405] uart_write+0xb5/0x270
[ 34.420170][ T3405] n_tty_write+0x311/0x480
[ 34.420394][ T3405] file_tty_write+0x16e/0x360
[ 34.420628][ T3405] redirected_tty_write+0x6a/0x90
[ 34.420877][ T3405] do_iter_readv_writev+0x104/0x140
[ 34.421134][ T3405] vfs_writev+0xba/0x240
[ 34.421350][ T3405] do_writev+0x5a/0xc0
[ 34.421559][ T3405] __ia32_sys_writev+0x12/0x20
[ 34.421797][ T3405] ia32_sys_call+0x1003/0x1100
[ 34.422034][ T3405] do_int80_syscall_32+0xa6/0xe0
[ 34.422281][ T3405] restore_all_switch_stack+0x0/0xb5
[ 34.422543][ T3405]
[ 34.422543][ T3405] -> #2 (&port_lock_key){-.-.}-{3:3}:
[ 34.422881][ T3405] _raw_spin_lock_irqsave+0x44/0x7c
[ 34.423137][ T3405] serial8250_console_write+0x5b/0x5b0
[ 34.423407][ T3405] univ8250_console_write+0x23/0x50
[ 34.423668][ T3405] console_flush_all+0x212/0x3e0
[ 34.423914][ T3405] console_unlock+0x45/0xc0
[ 34.424142][ T3405] vprintk_emit+0x156/0x240
[ 34.424369][ T3405] vprintk_default+0x10/0x20
[ 34.424601][ T3405] vprintk+0xe/0x20
[ 34.424797][ T3405] _printk+0x14/0x1c
[ 34.424999][ T3405] register_console+0x2f2/0x370
[ 34.425241][ T3405] univ8250_console_init+0x1b/0x28
[ 34.425494][ T3405] console_init+0x65/0x104
[ 34.425719][ T3405] start_kernel+0x203/0x364
[ 34.425946][ T3405] i386_start_kernel+0xd3/0xf4
[ 34.426184][ T3405] startup_32_smp+0x151/0x154
[ 34.426418][ T3405]
[ 34.426418][ T3405] -> #1 (console_owner){..-.}-{0:0}:
[ 34.426753][ T3405] console_lock_spinning_enable+0x44/0x50
[ 34.427033][ T3405] console_flush_all+0x1fb/0x3e0
[ 34.427280][ T3405] console_unlock+0x45/0xc0
[ 34.427507][ T3405] vprintk_emit+0x156/0x240
[ 34.427737][ T3405] vprintk_default+0x10/0x20
[ 34.427969][ T3405] vprintk+0xe/0x20
[ 34.428165][ T3405] _printk+0x14/0x1c
[ 34.428366][ T3405] ubsan_prologue+0x1e/0x70
[ 34.428594][ T3405] handle_overflow+0x57/0x1d0
[ 34.428828][ T3405] __ubsan_handle_sub_overflow+0x10/0x20
[ 34.429105][ T3405] visit_groups_merge+0x73a/0x740
[ 34.429355][ T3405] __pmu_ctx_sched_in+0x3a/0x50
[ 34.429597][ T3405] ctx_sched_in+0xf1/0x110
[ 34.429821][ T3405] ctx_resched+0xc6/0x1c0
[ 34.430041][ T3405] __perf_install_in_context+0x1c1/0x240
[ 34.430318][ T3405] remote_function+0x25/0x40
[ 34.430549][ T3405] smp_call_function_single+0x37/0x70
[ 34.430816][ T3405] perf_install_in_context+0x160/0x220
[ 34.431086][ T3405] __ia32_sys_perf_event_open+0x73a/0x860
[ 34.431367][ T3405] ia32_sys_call+0x739/0x1100
[ 34.431603][ T3405] do_int80_syscall_32+0xa6/0xe0
[ 34.431849][ T3405] restore_all_switch_stack+0x0/0xb5
[ 34.432111][ T3405]
[ 34.432111][ T3405] -> #0 (&ctx->lock){....}-{2:2}:
[ 34.432435][ T3405] __lock_acquire+0x15de/0x2920
[ 34.432677][ T3405] lock_acquire+0x94/0x190
[ 34.432901][ T3405] _raw_spin_lock+0x2a/0x5c
[ 34.433128][ T3405] __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.433413][ T3405] __schedule+0x61e/0x674
[ 34.433633][ T3405] preempt_schedule_irq+0xa8/0x110
[ 34.433886][ T3405] raw_irqentry_exit_cond_resched+0x34/0x40
[ 34.434175][ T3405] irqentry_exit+0x81/0x8c
[ 34.434399][ T3405] sysvec_apic_timer_interrupt+0x29/0x34
[ 34.434676][ T3405] handle_exception_return+0x0/0xc9
[ 34.434933][ T3405] smp_call_function_single+0x57/0x70
[ 34.435199][ T3405] perf_install_in_context+0x160/0x220
[ 34.435469][ T3405] __ia32_sys_perf_event_open+0x73a/0x860
[ 34.435752][ T3405] ia32_sys_call+0x739/0x1100
[ 34.435986][ T3405] do_int80_syscall_32+0xa6/0xe0
[ 34.436232][ T3405] restore_all_switch_stack+0x0/0xb5
[ 34.436495][ T3405]
[ 34.436495][ T3405] other info that might help us debug this:
[ 34.436495][ T3405]
[ 34.436949][ T3405] Chain exists of:
[ 34.436949][ T3405] &ctx->lock --> &p->pi_lock --> &rq->__lock
[ 34.436949][ T3405]
[ 34.437477][ T3405] Possible unsafe locking scenario:
[ 34.437477][ T3405]
[ 34.437810][ T3405] CPU0 CPU1
[ 34.438050][ T3405] ---- ----
[ 34.438290][ T3405] lock(&rq->__lock);
[ 34.438475][ T3405] lock(&p->pi_lock);
[ 34.438770][ T3405] lock(&rq->__lock);
[ 34.439064][ T3405] lock(&ctx->lock);
[ 34.439245][ T3405]
[ 34.439245][ T3405] *** DEADLOCK ***
[ 34.439245][ T3405]
[ 34.439609][ T3405] 3 locks held by trinity-main/3405:
[ 34.439847][ T3405] #0: ee7cd0e0 (&sig->exec_update_lock){++++}-{4:4}, at: __ia32_sys_perf_event_open+0x355/0x860
[ 34.440318][ T3405] #1: ec0b2468 (&ctx->mutex){+.+.}-{4:4}, at: __ia32_sys_perf_event_open+0x3f3/0x860
[ 34.440746][ T3405] #2: 828de790 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x61/0xc0
[ 34.441156][ T3405]
[ 34.441156][ T3405] stack backtrace:
[ 34.441420][ T3405] CPU: 0 UID: 65534 PID: 3405 Comm: trinity-main Tainted: G T 6.14.0-rc2-00025-gd70da12453ac #1
[ 34.441945][ T3405] Tainted: [T]=RANDSTRUCT
[ 34.442140][ T3405] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 34.442602][ T3405] Call Trace:
[ 34.442753][ T3405] __dump_stack+0x18/0x24
[ 34.442950][ T3405] dump_stack_lvl+0x32/0x74
[ 34.443157][ T3405] ? vprintk+0xe/0x20
[ 34.443339][ T3405] dump_stack+0xd/0x1c
[ 34.443525][ T3405] print_circular_bug+0x2c5/0x2d0
[ 34.443756][ T3405] check_noncircular+0xc7/0xf0
[ 34.443974][ T3405] ? local_clock_noinstr+0x17/0x140
[ 34.444208][ T3405] ? sched_clock_noinstr+0x8/0xc
[ 34.444433][ T3405] ? local_clock_noinstr+0x17/0x140
[ 34.444668][ T3405] __lock_acquire+0x15de/0x2920
[ 34.444889][ T3405] ? __lock_acquire+0x566/0x2920
[ 34.445114][ T3405] ? sched_clock_noinstr+0x8/0xc
[ 34.445338][ T3405] ? local_clock_noinstr+0x17/0x140
[ 34.445573][ T3405] ? __cgroup_account_cputime+0x17/0x40
[ 34.445825][ T3405] lock_acquire+0x94/0x190
[ 34.446028][ T3405] ? __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.446299][ T3405] ? local_clock+0xe/0x30
[ 34.446496][ T3405] ? __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.446766][ T3405] _raw_spin_lock+0x2a/0x5c
[ 34.446972][ T3405] ? __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.447242][ T3405] __perf_event_task_sched_out+0x2cf/0x3c0
[ 34.447505][ T3405] ? set_next_task_fair+0x66/0x210
[ 34.447738][ T3405] ? pick_next_task_fair+0x69/0x80
[ 34.447967][ T3405] __schedule+0x61e/0x674
[ 34.448165][ T3405] ? raw_irqentry_exit_cond_resched+0x34/0x40
[ 34.448439][ T3405] ? raw_irqentry_exit_cond_resched+0x34/0x40
[ 34.448714][ T3405] preempt_schedule_irq+0xa8/0x110
[ 34.448946][ T3405] raw_irqentry_exit_cond_resched+0x34/0x40
[ 34.449213][ T3405] irqentry_exit+0x81/0x8c
[ 34.449415][ T3405] ? vmware_sched_clock+0xdc/0xdc
[ 34.449644][ T3405] sysvec_apic_timer_interrupt+0x29/0x34
[ 34.449898][ T3405] ? event_function+0x150/0x150
[ 34.450119][ T3405] handle_exception+0x132/0x132
[ 34.450339][ T3405] EIP: smp_call_function_single+0x57/0x70
[ 34.450596][ T3405] Code: ce e8 3d d8 02 00 89 f0 ff d3 e8 34 d7 02 00 9c 8f 45 ec f7 45 ec 00 02 00 00 75 17 31 c0 f7 c7 00 02 00 00 74 01 fb 83 c4 08 <5e> 5f 5b 5d 31 c9 31 d2 c3 e8 f3 eb af 00 eb e2 90 90 90 90 90 90
[ 34.451460][ T3405] EAX: 00000000 EBX: 81204170 ECX: 00000000 EDX: 00000000
[ 34.451779][ T3405] ESI: ee6b3e94 EDI: 00000246 EBP: ee6b3e84 ESP: ee6b3e78
[ 34.452097][ T3405] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068 EFLAGS: 00000286
[ 34.452438][ T3405] ? event_function+0x150/0x150
[ 34.452659][ T3405] ? print_cfs_rq+0x6fb/0xd70
[ 34.452874][ T3405] ? vmware_sched_clock+0xdc/0xdc
[ 34.453102][ T3405] ? vmware_sched_clock+0xdc/0xdc
[ 34.453331][ T3405] ? smp_call_function_single+0x57/0x70
[ 34.453581][ T3405] perf_install_in_context+0x160/0x220
[ 34.453828][ T3405] ? add_event_to_ctx+0x4a0/0x4a0
[ 34.454056][ T3405] __ia32_sys_perf_event_open+0x73a/0x860
[ 34.454317][ T3405] ia32_sys_call+0x739/0x1100
[ 34.454530][ T3405] do_int80_syscall_32+0xa6/0xe0
[ 34.454755][ T3405] entry_INT80_32+0x124/0x124
[ 34.454968][ T3405] EIP: 0x77f7d092
[ 34.455134][ T3405] Code: 00 00 00 e9 90 ff ff ff ff a3 24 00 00 00 68 30 00 00 00 e9 80 ff ff ff ff a3 f8 ff ff ff 66 90 00 00 00 00 00 00 00 00 cd 80 <c3> 8d b4 26 00 00 00 00 8d b6 00 00 00 00 8b 1c 24 c3 8d b4 26 00
[ 34.456000][ T3405] EAX: ffffffda EBX: 00fc2ed0 ECX: 00000d4d EDX: ffffffff
[ 34.456317][ T3405] ESI: ffffffff EDI: 00000008 EBP: 77da8525 ESP: 7fe29698
[ 34.456634][ T3405] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000206
[ 34.733107][ T3405] UDPLite: UDP-Lite is deprecated and scheduled to be removed in 2025, please contact the netdev mailing list
[ 34.854852][ T3405] UDPLite6: UDP-Lite is deprecated and scheduled to be removed in 2025, please contact the netdev mailing list
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
Powered by blists - more mailing lists