Message-ID: <CAMuHMdWq9s3xn2eDebAfBj6ieLqwHhVhr0UuyQCtiBXz1eFnsw@mail.gmail.com>
Date: Tue, 11 Mar 2025 12:25:07 +0100
From: Geert Uytterhoeven <geert@...ux-m68k.org>
To: Saravana Kannan <saravanak@...gle.com>
Cc: "Rafael J. Wysocki" <rafael@...nel.org>, Pavel Machek <pavel@....cz>, Len Brown <len.brown@...el.com>, 
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>, Ingo Molnar <mingo@...hat.com>, 
	Peter Zijlstra <peterz@...radead.org>, Juri Lelli <juri.lelli@...hat.com>, 
	Vincent Guittot <vincent.guittot@...aro.org>, Dietmar Eggemann <dietmar.eggemann@....com>, 
	Steven Rostedt <rostedt@...dmis.org>, Ben Segall <bsegall@...gle.com>, Mel Gorman <mgorman@...e.de>, 
	Valentin Schneider <vschneid@...hat.com>, Marek Vasut <marex@...x.de>, Bird@...gle.com, 
	Tim <Tim.Bird@...y.com>, kernel-team@...roid.com, linux-pm@...r.kernel.org, 
	linux-kernel@...r.kernel.org
Subject: Re: [PATCH v1 4/5] PM: sleep: Do breadth first suspend/resume for
 async suspend/resume

Hi Saravana,

On Thu, 14 Nov 2024 at 23:09, Saravana Kannan <saravanak@...gle.com> wrote:
> The dpm_list used for suspend/resume ensures that all superior devices
> (parents and suppliers) precede subordinate devices (children and
> consumers).
>
> Current async resume logic:
> -------------------------------
> * For each resume phase (except the "complete" phase, which is always
>   serialized), the resume logic first queues all async devices in the
>   dpm_list. It then loops through the dpm_list again to resume the sync
>   devices one by one.
>
> * Async devices wait for all their superior devices to resume before
>   starting their own resume operation.
>
> * This process results in multiple sleep and wake-up cycles before an
>   async device actually resumes. This sleeping also causes kworker
>   threads to stall with work for a period. Consequently, the workqueue
>   framework spins up more kworker threads to handle the other async
>   devices.
>
> * The end result is excessive thread creation, wake-ups, sleeps, and
>   context switches for every async device. This overhead makes a full
>   async resume (with all devices marked as async-capable) much slower
>   than a synchronous resume.
>
> Current async suspend logic:
> --------------------------------
> * The async suspend logic differs from the async resume logic. The
>   suspend logic loops through the dpm_list. When it finds an async
>   device, it queues the work and moves on. However, if it encounters a
>   sync device, it waits until the sync device (and all its subordinate
>   devices) have suspended before proceeding to the next device.
>   Therefore, an async suspend device can be left waiting on an
>   unrelated device before even being queued.
>
> * Once queued, an async device experiences the same inefficiencies as
>   in the resume logic (thread creation, wake-ups, sleeps, and context
>   switches).
>
> On a Pixel 6, averaging over 100 suspend/resume cycles, the data is as
> follows:
>
> +---------------------------+-----------+------------+----------+
> | Phase                     | Full sync | Full async | % change |
> +---------------------------+-----------+------------+----------+
> | Total dpm_suspend*() time |    107 ms |      72 ms |     -33% |
> +---------------------------+-----------+------------+----------+
> | Total dpm_resume*() time  |     75 ms |      90 ms |     +20% |
> +---------------------------+-----------+------------+----------+
> | Sum                       |    182 ms |     162 ms |     -11% |
> +---------------------------+-----------+------------+----------+
>
> This shows that full async suspend/resume is not a viable option. It
> makes the user-visible resume phase slower and only improves the
> overall time by 11%.
>
> To fix all this, this patches introduces a new async suspend/resume
> logic.
>
> New suspend/resume logic:
> -------------------------
> * For each suspend/resume phase (except "complete" and "prepare,"
>   which are always serialized), the logic first queues only the async
>   devices that don't have to wait for any subordinates (for suspend)
>   or superiors (for resume). It then loops through the dpm_list again
>   to suspend/resume the sync devices one by one.
>
> * When a device (sync or async) successfully suspends/resumes, it
>   examines its superiors/subordinates and queues only the async
>   devices that don't need to wait for any subordinates/superiors.
>
> With this new logic:
>
> * Queued async devices don't have to wait for completion and are
>   always ready to perform their suspend/resume operation.
>
> * The queue of async devices remains short.
>
> * kworkers never sleep for extended periods, and the workqueue
>   framework doesn't spin up many new threads to handle a backlog of
>   async devices.
>
> * The result is approximately NCPU kworker threads running in parallel
>   without sleeping until all async devices finish.
>
> On a Pixel 6, averaging over 100 suspend/resume cycles, the new logic
> yields improved results:
> +---------------------------+-----------+------------+------------------+
> | Phase                     | Old full sync | New full async | % change |
> +---------------------------+-----------+------------+------------------+
> | Total dpm_suspend*() time |        107 ms |          60 ms |     -44% |
> +---------------------------+-----------+------------+------------------+
> | Total dpm_resume*() time  |         75 ms |          74 ms |      -1% |
> +---------------------------+-----------+------------+------------------+
> | Sum                       |        182 ms |         134 ms |     -26% |
> +---------------------------+-----------+------------+------------------+
>
> Signed-off-by: Saravana Kannan <saravanak@...gle.com>

Thanks for your patch!

On Renesas Gray Hawk Single (R-Car V4M) during s2idle:

PM: suspend entry (s2idle)
Filesystems sync: 0.055 seconds
Freezing user space processes
Freezing user space processes completed (elapsed 0.004 seconds)
OOM killer disabled.
Freezing remaining freezable tasks
Freezing remaining freezable tasks completed (elapsed 0.003 seconds)

================================
WARNING: inconsistent lock state
6.14.0-rc5-rcar3-05904-g1ec95427acf9 #261 Tainted: G        W
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
s2idle/764 [HC0[0]:SC0[0]:HE1:SE1] takes:
ffffff844392c190 (&dev->power.lock){?.-.}-{3:3}, at: dpm_async_fn+0x24/0xa8
{IN-HARDIRQ-W} state was registered at:
  lock_acquire+0x26c/0x2c4
  _raw_spin_lock_irqsave+0x54/0x70
  pm_suspend_timer_fn+0x20/0x78
  __hrtimer_run_queues+0x204/0x330
  hrtimer_interrupt+0xa8/0x1b0
  arch_timer_handler_virt+0x28/0x3c
  handle_percpu_devid_irq+0x64/0x110
  handle_irq_desc+0x3c/0x50
  generic_handle_domain_irq+0x18/0x20
  gic_handle_irq+0x50/0xbc
  call_on_irq_stack+0x24/0x34
  do_interrupt_handler+0x60/0x88
  el1_interrupt+0x30/0x48
  el1h_64_irq_handler+0x14/0x1c
  el1h_64_irq+0x70/0x74
  cpuidle_enter_state+0x1a4/0x2d0
  cpuidle_enter+0x34/0x48
  do_idle+0x21c/0x240
  cpu_startup_entry+0x30/0x34
  kernel_init+0x0/0x124
  console_on_rootfs+0x0/0x64
  __primary_switched+0x88/0x90
irq event stamp: 17055
hardirqs last  enabled at (17055): [<ffffffc080a0782c>]
_raw_spin_unlock_irqrestore+0x34/0x54
hardirqs last disabled at (17054): [<ffffffc080a075a4>]
_raw_spin_lock_irqsave+0x28/0x70
softirqs last  enabled at (14360): [<ffffffc080096bcc>]
handle_softirqs+0x1b0/0x3b4
softirqs last disabled at (14355): [<ffffffc080010168>] __do_softirq+0x10/0x18

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&dev->power.lock);
  <Interrupt>
    lock(&dev->power.lock);

 *** DEADLOCK ***

5 locks held by s2idle/764:
 #0: ffffff84400983f0 (sb_writers#5){.+.+}-{0:0}, at:
file_start_write.isra.0+0x24/0x30
 #1: ffffff8446802288 (&of->mutex#2){+.+.}-{4:4}, at:
kernfs_fop_write_iter+0xf8/0x180
 #2: ffffff8440d016e8 (kn->active#39){.+.+}-{0:0}, at:
kernfs_fop_write_iter+0x100/0x180
 #3: ffffffc0812f4780 (system_transition_mutex){+.+.}-{4:4}, at:
pm_suspend+0x84/0x248
 #4: ffffffc084bb7f78 (dpm_list_mtx){+.+.}-{4:4}, at: dpm_suspend+0x84/0x1a8

stack backtrace:
CPU: 0 UID: 0 PID: 764 Comm: s2idle Tainted: G        W
6.14.0-rc5-rcar3-05904-g1ec95427acf9 #261
Tainted: [W]=WARN
Hardware name: Renesas Gray Hawk Single board based on r8a779h0 (DT)
Call trace:
 show_stack+0x14/0x1c (C)
 dump_stack_lvl+0x78/0xa8
 dump_stack+0x14/0x1c
 print_usage_bug+0x1dc/0x1f8
 mark_lock+0x1c4/0x3a4
 __lock_acquire+0x560/0x1038
 lock_acquire+0x26c/0x2c4
 _raw_spin_lock+0x40/0x54
 dpm_async_fn+0x24/0xa8
 dpm_async_queue_suspend_ready_fn+0x40/0x50
 dpm_async_suspend_loop+0x48/0x50
 dpm_suspend+0x94/0x1a8
 dpm_suspend_start+0x68/0x70
 suspend_devices_and_enter+0xd8/0x59c
 pm_suspend+0x214/0x248
 state_store+0xa8/0xe8
 kobj_attr_store+0x14/0x24
 sysfs_kf_write+0x4c/0x64
 kernfs_fop_write_iter+0x138/0x180
 vfs_write+0x148/0x1b4
 ksys_write+0x78/0xe0
 __arm64_sys_write+0x14/0x1c
 invoke_syscall+0x68/0xf0
 el0_svc_common.constprop.0+0xb0/0xcc
 do_el0_svc+0x18/0x20
 el0_svc+0x38/0x90
 el0t_64_sync_handler+0x80/0x130
 el0t_64_sync+0x158/0x15c


Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@...ux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Powered by blists - more mailing lists