Re: [linus:master] [sched/eevdf] eab03c23c2: WARNING:possible_circular_locking_dependency_detected

From: Chen Yu
Date: Mon Apr 01 2024 - 22:37:07 EST


Hi Oliver,

On 2024-04-01 at 23:21:11 +0800, kernel test robot wrote:
>
>
> Hello,
>
> kernel test robot noticed "WARNING:possible_circular_locking_dependency_detected" on:
>
> commit: eab03c23c2a162085b13200d7942fc5a00b5ccc8 ("sched/eevdf: Fix vruntime adjustment on reweight")
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
>
> [test failed on linus/master 4076fa161217fcd64a578ca04586c4be728cb004]
>
>

Should be the known issue that when no eligible entity is found, there was
a printk warning which triggered this. In latest kernel this printk was
removed(but yes, it could return a NULL as you reported previously). Yujie
has helped me setup the similar environment as lkp for this trinity test,
I'll do some tests to investigate the NULL pointer issue..

thanks,
Chenyu

> in testcase: trinity
> version:
> with following parameters:
>
> runtime: 300s
> group: group-01
> nr_groups: 5
>
>
>
> compiler: clang-17
> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
> this issue doesn't always happen, 36 times out of 308 runs as below.
> but for parent, we never observed this issue.
>
>
> v6.7-rc1 eab03c23c2a162085b13200d794
> ---------------- ---------------------------
> fail:runs %reproduction fail:runs
> | | |
> :308 12% 36:308 dmesg.WARNING:possible_circular_locking_dependency_detected
>
>
>
>
> 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/202404012303.41984b81-lkp@xxxxxxxxx
>
>
> [ 195.727401][ T3470] WARNING: possible circular locking dependency detected
> [ 195.727403][ T3470] 6.7.0-rc1-00001-geab03c23c2a1 #1 Tainted: G TN
> [ 195.727404][ T3470] ------------------------------------------------------
> [ 195.727405][ T3470] trinity-main/3470 is trying to acquire lock:
> [ 195.727407][ T3470] cb267a18 (console_owner){-.-.}-{0:0}, at: console_lock_spinning_enable (kernel/printk/printk.c:1854)
> [ 195.727416][ T3470]
> [ 195.727416][ T3470] but task is already holding lock:
> [ 195.727417][ T3470] da2d4350 (&rq->__lock){-.-.}-{2:2}, at: __schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:560 kernel/sched/sched.h:1349 kernel/sched/sched.h:1663 kernel/sched/core.c:6604)
> [ 195.727423][ T3470]
> [ 195.727423][ T3470] which lock already depends on the new lock.
> [ 195.727423][ T3470]
> [ 195.727424][ T3470]
> [ 195.727424][ T3470] the existing dependency chain (in reverse order) is:
> [ 195.727424][ T3470]
> [ 195.727424][ T3470] -> #4 (&rq->__lock){-.-.}-{2:2}:
> [ 195.727428][ T3470] _raw_spin_lock_nested (kernel/locking/spinlock.c:378)
> [ 195.727431][ T3470] raw_spin_rq_lock_nested (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:560)
> [ 195.727433][ T3470] task_fork_fair (kernel/sched/sched.h:1581)
> [ 195.727436][ T3470] sched_cgroup_fork (kernel/sched/core.c:?)
> [ 195.727438][ T3470] copy_process (include/linux/timekeeping.h:154 kernel/fork.c:2619)
> [ 195.727441][ T3470] kernel_clone (kernel/fork.c:2907)
> [ 195.727443][ T3470] user_mode_thread (kernel/fork.c:2985)
> [ 195.727445][ T3470] rest_init (init/main.c:695)
> [ 195.727447][ T3470] start_kernel (init/main.c:875)
> [ 195.727452][ T3470] start_kernel (init/main.c:1072)
> [ 195.727454][ T3470] i386_start_kernel (arch/x86/kernel/head32.c:79)
> [ 195.727457][ T3470] startup_32_smp (arch/x86/kernel/head_32.S:295)
> [ 195.727459][ T3470]
> [ 195.727459][ T3470] -> #3 (&p->pi_lock){-.-.}-{2:2}:
> [ 195.727461][ T3470] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
> [ 195.727464][ T3470] try_to_wake_up (kernel/sched/core.c:2232)
> [ 195.727466][ T3470] default_wake_function (kernel/sched/core.c:7020)
> [ 195.727469][ T3470] woken_wake_function (kernel/sched/wait.c:444)
> [ 195.727472][ T3470] __wake_up_common_lock (kernel/sched/wait.c:89)
> [ 195.727474][ T3470] __wake_up (kernel/sched/wait.c:127)
> [ 195.727476][ T3470] tty_wakeup (drivers/tty/tty_io.c:527)
> [ 195.727478][ T3470] tty_port_default_wakeup (drivers/tty/tty_port.c:70)
> [ 195.727482][ T3470] tty_port_tty_wakeup (drivers/tty/tty_port.c:434)
> [ 195.727484][ T3470] uart_write_wakeup (drivers/tty/serial/serial_core.c:121)
> [ 195.727486][ T3470] serial8250_tx_chars (drivers/tty/serial/8250/8250_port.c:1842)
> [ 195.727490][ T3470] serial8250_handle_irq (include/linux/spinlock.h:406 include/linux/serial_core.h:667 include/linux/serial_core.h:1085 drivers/tty/serial/8250/8250_port.c:1947)
> [ 195.727492][ T3470] serial8250_default_handle_irq (drivers/tty/serial/8250/8250_port.c:1962)
> [ 195.727495][ T3470] serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:127)
> [ 195.727498][ T3470] __handle_irq_event_percpu (kernel/irq/handle.c:158)
> [ 195.727500][ T3470] handle_irq_event (kernel/irq/handle.c:193 kernel/irq/handle.c:210)
> [ 195.727503][ T3470] handle_edge_irq (kernel/irq/chip.c:833)
> [ 195.727505][ T3470] __handle_irq (arch/x86/kernel/irq_32.c:97)
> [ 195.727508][ T3470] __common_interrupt (include/asm-generic/irq_regs.h:28 arch/x86/kernel/irq.c:270)
> [ 195.727510][ T3470] common_interrupt (arch/x86/kernel/irq.c:247)
> [ 195.727512][ T3470] asm_common_interrupt (arch/x86/entry/entry_32.S:636)
> [ 195.727515][ T3470] _raw_spin_unlock_irqrestore (kernel/locking/spinlock.c:195)
> [ 195.727517][ T3470] __create_object (mm/kmemleak.c:753)
> [ 195.727521][ T3470] kmemleak_alloc (mm/kmemleak.c:761 mm/kmemleak.c:1033)
> [ 195.727523][ T3470] slab_post_alloc_hook (include/linux/kmemleak.h:42)
> [ 195.727527][ T3470] kmem_cache_alloc_bulk (mm/slub.c:4056)
> [ 195.727529][ T3470] mas_alloc_nodes (lib/maple_tree.c:165 lib/maple_tree.c:1287)
> [ 195.727532][ T3470] mas_expected_entries (lib/maple_tree.c:5633)
> [ 195.727534][ T3470] copy_mm (include/linux/mm.h:994 kernel/fork.c:681 kernel/fork.c:1691 kernel/fork.c:1740)
> [ 195.727536][ T3470] copy_process (kernel/fork.c:?)
> [ 195.727538][ T3470] kernel_clone (kernel/fork.c:2907)
> [ 195.727540][ T3470] __ia32_sys_clone (kernel/fork.c:3018)
> [ 195.727542][ T3470] do_int80_syscall_32 (arch/x86/entry/common.c:164)
> [ 195.727544][ T3470] restore_all_switch_stack (arch/x86/entry/entry_32.S:947)
> [ 195.727547][ T3470]
> [ 195.727547][ T3470] -> #2 (&tty->write_wait){-.-.}-{2:2}:
> [ 195.727550][ T3470] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
> [ 195.727552][ T3470] __wake_up_common_lock (kernel/sched/wait.c:?)
> [ 195.727554][ T3470] __wake_up (kernel/sched/wait.c:127)
> [ 195.727556][ T3470] tty_wakeup (drivers/tty/tty_io.c:527)
> [ 195.727558][ T3470] tty_port_default_wakeup (drivers/tty/tty_port.c:70)
> [ 195.727560][ T3470] tty_port_tty_wakeup (drivers/tty/tty_port.c:434)
> [ 195.727563][ T3470] uart_write_wakeup (drivers/tty/serial/serial_core.c:121)
> [ 195.727564][ T3470] serial8250_tx_chars (drivers/tty/serial/8250/8250_port.c:1842)
> [ 195.727567][ T3470] serial8250_handle_irq (include/linux/spinlock.h:406 include/linux/serial_core.h:667 include/linux/serial_core.h:1085 drivers/tty/serial/8250/8250_port.c:1947)
> [ 195.727569][ T3470] serial8250_default_handle_irq (drivers/tty/serial/8250/8250_port.c:1962)
> [ 195.727572][ T3470] serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:127)
> [ 195.727574][ T3470] __handle_irq_event_percpu (kernel/irq/handle.c:158)
> [ 195.727577][ T3470] handle_irq_event (kernel/irq/handle.c:193 kernel/irq/handle.c:210)
> [ 195.727579][ T3470] handle_edge_irq (kernel/irq/chip.c:833)
> [ 195.727581][ T3470] __handle_irq (arch/x86/kernel/irq_32.c:97)
> [ 195.727583][ T3470] __common_interrupt (include/asm-generic/irq_regs.h:28 arch/x86/kernel/irq.c:270)
> [ 195.727585][ T3470] common_interrupt (arch/x86/kernel/irq.c:247)
> [ 195.727586][ T3470] asm_common_interrupt (arch/x86/entry/entry_32.S:636)
> [ 195.727588][ T3470] _raw_spin_unlock_irqrestore (kernel/locking/spinlock.c:195)
> [ 195.727590][ T3470] uart_write (drivers/tty/serial/serial_core.c:74 drivers/tty/serial/serial_core.c:617)
> [ 195.727592][ T3470] n_tty_write (drivers/tty/n_tty.c:574 drivers/tty/n_tty.c:2379)
> [ 195.727594][ T3470] file_tty_write (drivers/tty/tty_io.c:1021)
> [ 195.727596][ T3470] redirected_tty_write (drivers/tty/tty_io.c:1113 drivers/tty/tty_io.c:1136)
> [ 195.727598][ T3470] vfs_write (fs/read_write.c:492)
> [ 195.727600][ T3470] ksys_write (fs/read_write.c:637)
> [ 195.727602][ T3470] __ia32_sys_write (fs/read_write.c:646)
> [ 195.727604][ T3470] do_int80_syscall_32 (arch/x86/entry/common.c:164)
> [ 195.727606][ T3470] restore_all_switch_stack (arch/x86/entry/entry_32.S:947)
> [ 195.727608][ T3470]
> [ 195.727608][ T3470] -> #1 (&port_lock_key){-.-.}-{2:2}:
> [ 195.727611][ T3470] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:110 kernel/locking/spinlock.c:162)
> [ 195.727613][ T3470] serial8250_console_write (include/linux/serial_core.h:? drivers/tty/serial/8250/8250_port.c:3403)
> [ 195.727615][ T3470] univ8250_console_write (drivers/tty/serial/8250/8250_core.c:601)
> [ 195.727618][ T3470] console_flush_all (kernel/printk/printk.c:2905)
> [ 195.727620][ T3470] console_unlock (kernel/printk/printk.c:3036)
> [ 195.727622][ T3470] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304)
> [ 195.727623][ T3470] vprintk_default (kernel/printk/printk.c:2318)
> [ 195.727625][ T3470] vprintk (kernel/printk/printk_safe.c:?)
> [ 195.727627][ T3470] _printk (kernel/printk/printk.c:2328)
> [ 195.727630][ T3470] register_console (kernel/printk/printk.c:3542)
> [ 195.727632][ T3470] univ8250_console_init (drivers/tty/serial/8250/8250_core.c:?)
> [ 195.727635][ T3470] console_init (include/linux/jump_label.h:270 include/trace/events/initcall.h:48 kernel/printk/printk.c:3689)
> [ 195.727637][ T3470] start_kernel (init/main.c:1009)
> [ 195.727640][ T3470] i386_start_kernel (arch/x86/kernel/head32.c:79)
> [ 195.727642][ T3470] startup_32_smp (arch/x86/kernel/head_32.S:295)
> [ 195.727644][ T3470]
> [ 195.727644][ T3470] -> #0 (console_owner){-.-.}-{0:0}:
> [ 195.727646][ T3470] __lock_acquire (kernel/locking/lockdep.c:?)
> [ 195.727649][ T3470] lock_acquire (kernel/locking/lockdep.c:5753)
> [ 195.727651][ T3470] console_lock_spinning_enable (kernel/printk/printk.c:1854)
> [ 195.727653][ T3470] console_flush_all (kernel/printk/printk.c:2901)
> [ 195.727655][ T3470] console_unlock (kernel/printk/printk.c:3036)
> [ 195.727657][ T3470] vprintk_emit (arch/x86/include/asm/preempt.h:85 kernel/printk/printk.c:2304)
> [ 195.727658][ T3470] vprintk_default (kernel/printk/printk.c:2318)
> [ 195.727660][ T3470] vprintk (kernel/printk/printk_safe.c:?)
> [ 195.727662][ T3470] _printk (kernel/printk/printk.c:2328)
> [ 195.727665][ T3470] pick_eevdf (kernel/sched/fair.c:961)
> [ 195.727667][ T3470] pick_next_task_fair (kernel/sched/sched.h:1417 kernel/sched/fair.c:8377)
> [ 195.727669][ T3470] __schedule (kernel/sched/core.c:5998)
> [ 195.727672][ T3470] schedule (arch/x86/include/asm/preempt.h:85 kernel/sched/core.c:6764 kernel/sched/core.c:6778)
> [ 195.727674][ T3470] schedule_hrtimeout_range_clock (kernel/time/hrtimer.c:?)
> [ 195.727676][ T3470] schedule_hrtimeout_range (kernel/time/hrtimer.c:2364)
> [ 195.727678][ T3470] do_sigtimedwait (kernel/signal.c:3653)
> [ 195.727680][ T3470] __ia32_sys_rt_sigtimedwait_time32 (kernel/signal.c:3729)
> [ 195.727683][ T3470] __do_fast_syscall_32 (arch/x86/entry/common.c:164)
> [ 195.727685][ T3470] do_fast_syscall_32 (arch/x86/entry/common.c:255)
> [ 195.727686][ T3470] do_SYSENTER_32 (arch/x86/entry/common.c:293)
> [ 195.727688][ T3470] entry_SYSENTER_32 (arch/x86/entry/entry_32.S:840)
> [ 195.727690][ T3470]
> [ 195.727690][ T3470] other info that might help us debug this:
> [ 195.727690][ T3470]
> [ 195.727691][ T3470] Chain exists of:
> [ 195.727691][ T3470] console_owner --> &p->pi_lock --> &rq->__lock
> [ 195.727691][ T3470]
> [ 195.727695][ T3470] Possible unsafe locking scenario:
> [ 195.727695][ T3470]
> [ 195.727695][ T3470] CPU0 CPU1
> [ 195.727696][ T3470] ---- ----
> [ 195.727696][ T3470] lock(&rq->__lock);
> [ 195.727698][ T3470] lock(&p->pi_lock);
> [ 195.727699][ T3470] lock(&rq->__lock);
> [ 195.727701][ T3470] lock(console_owner);
> [ 195.727702][ T3470]
> [ 195.727702][ T3470] *** DEADLOCK ***
> [ 195.727702][ T3470]
> [ 195.727703][ T3470] 3 locks held by trinity-main/3470:
>
>
> The kernel config and materials to reproduce are available at:
> https://download.01.org/0day-ci/archive/20240401/202404012303.41984b81-lkp@xxxxxxxxx
>
>
>
> --
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki
>