[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

Commit Message

kernel test robot March 21, 2025, 6:47 a.m. UTC

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:




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 <[e-mail]>
| Closes: https://lore.kernel.org/oe-lkp/[e-mail]


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250320/[e-mail]


[   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

Patch

--- /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