Re: [PATCH] sched/fair: fix pick_eevdf to always find the correct se

From: Marek Szyprowski
Date: Wed Oct 04 2023 - 16:39:52 EST


Hi,

On 30.09.2023 02:09, Benjamin Segall wrote:
> The old pick_eevdf could fail to find the actual earliest eligible
> deadline when it descended to the right looking for min_deadline, but it
> turned out that that min_deadline wasn't actually eligible. In that case
> we need to go back and search through any left branches we skipped
> looking for the actual best _eligible_ min_deadline.
>
> This is more expensive, but still O(log n), and at worst should only
> involve descending two branches of the rbtree.
>
> I've run this through a userspace stress test (thank you
> tools/lib/rbtree.c), so hopefully this implementation doesn't miss any
> corner cases.
>
> Fixes: 147f3efaa241 ("sched/fair: Implement an EEVDF-like scheduling policy")
> Signed-off-by: Ben Segall <bsegall@xxxxxxxxxx>

This patch landed in today's linux-next as commit 561c58efd239
("sched/fair: Fix pick_eevdf()"). Surprisingly it introduced a warning
about circular locking dependency. It can be easily observed during boot
from time to time on on qemu/arm64 'virt' machine:

======================================================
WARNING: possible circular locking dependency detected
6.6.0-rc4+ #7222 Not tainted
------------------------------------------------------
systemd-udevd/1187 is trying to acquire lock:
ffffbcc2be0c4de0 (console_owner){..-.}-{0:0}, at:
console_flush_all+0x1b0/0x500

but task is already holding lock:
ffff5535ffdd2b18 (&rq->__lock){-.-.}-{2:2}, at: __schedule+0xe0/0xc40

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #4 (&rq->__lock){-.-.}-{2:2}:
       _raw_spin_lock_nested+0x44/0x5c
       raw_spin_rq_lock_nested+0x24/0x40
       task_fork_fair+0x3c/0xac
       sched_cgroup_fork+0xe8/0x14c
       copy_process+0x11c4/0x1a14
       kernel_clone+0x8c/0x400
       user_mode_thread+0x70/0x98
       rest_init+0x28/0x190
       arch_post_acpi_subsys_init+0x0/0x8
       start_kernel+0x594/0x684
       __primary_switched+0xbc/0xc4

-> #3 (&p->pi_lock){-.-.}-{2:2}:
       _raw_spin_lock_irqsave+0x60/0x88
       try_to_wake_up+0x58/0x468
       default_wake_function+0x14/0x20
       woken_wake_function+0x20/0x2c
       __wake_up_common+0x94/0x170
       __wake_up_common_lock+0x7c/0xcc
       __wake_up+0x18/0x24
       tty_wakeup+0x34/0x70
       tty_port_default_wakeup+0x20/0x38
       tty_port_tty_wakeup+0x18/0x24
       uart_write_wakeup+0x18/0x28
       pl011_tx_chars+0x140/0x2b4
       pl011_start_tx+0xe8/0x190
       serial_port_runtime_resume+0x90/0xc0
       __rpm_callback+0x48/0x1a8
       rpm_callback+0x6c/0x78
       rpm_resume+0x438/0x6d8
       pm_runtime_work+0x84/0xc8
       process_one_work+0x1ec/0x53c
       worker_thread+0x298/0x408
       kthread+0x124/0x128
       ret_from_fork+0x10/0x20

-> #2 (&tty->write_wait){....}-{2:2}:
       _raw_spin_lock_irqsave+0x60/0x88
       __wake_up_common_lock+0x5c/0xcc
       __wake_up+0x18/0x24
       tty_wakeup+0x34/0x70
       tty_port_default_wakeup+0x20/0x38
       tty_port_tty_wakeup+0x18/0x24
       uart_write_wakeup+0x18/0x28
       pl011_tx_chars+0x140/0x2b4
       pl011_start_tx+0xe8/0x190
       serial_port_runtime_resume+0x90/0xc0
       __rpm_callback+0x48/0x1a8
       rpm_callback+0x6c/0x78
       rpm_resume+0x438/0x6d8
       pm_runtime_work+0x84/0xc8
       process_one_work+0x1ec/0x53c
       worker_thread+0x298/0x408
       kthread+0x124/0x128
       ret_from_fork+0x10/0x20

-> #1 (&port_lock_key){..-.}-{2:2}:
       _raw_spin_lock+0x48/0x60
       pl011_console_write+0x13c/0x1b0
       console_flush_all+0x20c/0x500
       console_unlock+0x6c/0x130
       vprintk_emit+0x228/0x3a0
       vprintk_default+0x38/0x44
       vprintk+0xa4/0xc0
       _printk+0x5c/0x84
       register_console+0x1f4/0x420
       serial_core_register_port+0x5a4/0x5d8
       serial_ctrl_register_port+0x10/0x1c
       uart_add_one_port+0x10/0x1c
       pl011_register_port+0x70/0x12c
       pl011_probe+0x1bc/0x1fc
       amba_probe+0x110/0x1c8
       really_probe+0x148/0x2b4
       __driver_probe_device+0x78/0x12c
       driver_probe_device+0xd8/0x160
       __device_attach_driver+0xb8/0x138
       bus_for_each_drv+0x84/0xe0
       __device_attach+0xa8/0x1b0
       device_initial_probe+0x14/0x20
       bus_probe_device+0xb0/0xb4
       device_add+0x574/0x738
       amba_device_add+0x40/0xac
       of_platform_bus_create+0x2b4/0x378
       of_platform_populate+0x50/0xfc
       of_platform_default_populate_init+0xd0/0xf0
       do_one_initcall+0x74/0x2f0
       kernel_init_freeable+0x28c/0x4dc
       kernel_init+0x24/0x1dc
       ret_from_fork+0x10/0x20

-> #0 (console_owner){..-.}-{0:0}:
       __lock_acquire+0x1318/0x20c4
       lock_acquire+0x1e8/0x318
       console_flush_all+0x1f8/0x500
       console_unlock+0x6c/0x130
       vprintk_emit+0x228/0x3a0
       vprintk_default+0x38/0x44
       vprintk+0xa4/0xc0
       _printk+0x5c/0x84
       pick_next_task_fair+0x28c/0x498
       __schedule+0x164/0xc40
       do_task_dead+0x54/0x58
       do_exit+0x61c/0x9e8
       do_group_exit+0x34/0x90
       __wake_up_parent+0x0/0x30
       invoke_syscall+0x48/0x114
       el0_svc_common.constprop.0+0x40/0xe0
       do_el0_svc_compat+0x1c/0x38
       el0_svc_compat+0x48/0xb4
       el0t_32_sync_handler+0x90/0x140
       el0t_32_sync+0x194/0x198

other info that might help us debug this:

Chain exists of:
  console_owner --> &p->pi_lock --> &rq->__lock

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&rq->__lock);
                               lock(&p->pi_lock);
                               lock(&rq->__lock);
  lock(console_owner);

 *** DEADLOCK ***

3 locks held by systemd-udevd/1187:
 #0: ffff5535ffdd2b18 (&rq->__lock){-.-.}-{2:2}, at: __schedule+0xe0/0xc40
 #1: ffffbcc2be0c4c30 (console_lock){+.+.}-{0:0}, at:
vprintk_emit+0x11c/0x3a0
 #2: ffffbcc2be0c4c88 (console_srcu){....}-{0:0}, at:
console_flush_all+0x7c/0x500

stack backtrace:
CPU: 1 PID: 1187 Comm: systemd-udevd Not tainted 6.6.0-rc4+ #7222
Hardware name: linux,dummy-virt (DT)
Call trace:
 dump_backtrace+0x98/0xf0
 show_stack+0x18/0x24
 dump_stack_lvl+0x60/0xac
 dump_stack+0x18/0x24
 print_circular_bug+0x290/0x370
 check_noncircular+0x15c/0x170
 __lock_acquire+0x1318/0x20c4
 lock_acquire+0x1e8/0x318
 console_flush_all+0x1f8/0x500
 console_unlock+0x6c/0x130
 vprintk_emit+0x228/0x3a0
 vprintk_default+0x38/0x44
 vprintk+0xa4/0xc0
 _printk+0x5c/0x84
 pick_next_task_fair+0x28c/0x498
 __schedule+0x164/0xc40
 do_task_dead+0x54/0x58
 do_exit+0x61c/0x9e8
 do_group_exit+0x34/0x90
 __wake_up_parent+0x0/0x30
 invoke_syscall+0x48/0x114
 el0_svc_common.constprop.0+0x40/0xe0
 do_el0_svc_compat+0x1c/0x38
 el0_svc_compat+0x48/0xb4
 el0t_32_sync_handler+0x90/0x140
 el0t_32_sync+0x194/0x198

The problem is probably elsewhere, but this scheduler change only
revealed it in a fully reproducible way. Reverting $subject on top of
linux-next hides the problem deep enough that I was not able to
reproduce it. Let me know if there is anything I can do to help fixing
this issue.

> ---
> kernel/sched/fair.c | 72 ++++++++++++++++++++++++++++++++++++---------
> 1 file changed, 58 insertions(+), 14 deletions(-)
>
> ...

Best regards
--
Marek Szyprowski, PhD
Samsung R&D Institute Poland