lkml.org 
[lkml]   [2020]   [Jun]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    From
    SubjectRe: power-off delay/hang due to commit 6d25be57 (mainline)
    Date
    On Thu, 11 Jun 2020 00:49:26 +0200 Stephen Berman <stephen.berman@gmx.net> wrote:

    > On Wed, 10 Jun 2020 12:25:14 +0200 Sebastian Andrzej Siewior
    > <bigeasy@linutronix.de> wrote:
    > [...]
    >>> By the other patch do you mean the following? (This email was also put
    >>> into my spam by GMX and AFAICT has not yet shown up on the vger list.)
    >>
    >> Yes. But now that I played a little with it, I made dis:
    > [...]
    >> So you should have output like:
    >> |[ 14.131696] Flushing events_freezable_power_
    >> the flush that hangs
    >>
    >> |[ 17.203246] Flushing events_freezable_power_ over, 0
    >> It has been noticed (0 at the end)
    >>
    >> |[ 17.203849] Showing busy workqueues and worker pools:
    >> |[ 17.204400] workqueue events_freezable_power_: flags=0x84
    >> |[ 17.205009] pwq 12: cpus=6 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    >> |[ 17.205774] in-flight: 2147:disk_events_workfn
    >> |[ 17.206268] workqueue kblockd: flags=0x18
    >> |[ 17.206682] pwq 13: cpus=6 node=0 flags=0x0 nice=-20 active=1/256 refcnt=2
    >> |[ 17.207428] pending: blk_mq_requeue_work
    >> |[ 17.207958] pool 12: cpus=6 node=0 flags=0x0 nice=0 hung=2s workers=3 idle:
    >> | 535 42
    >>
    >> A dump of all pending worqueue items.
    >>
    >> |[ 20.275239] Flushing events_freezable_power_ over, 0
    >> |[ 20.275812] Showing busy workqueues and worker pools:
    >> |[ 20.276385] workqueue events_freezable_power_: flags=0x84
    >> |[ 20.276972] pwq 12: cpus=6 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    >> |[ 20.277712] in-flight: 2147:disk_events_workfn
    >> |[ 20.278245] workqueue kblockd: flags=0x18
    >> |[ 20.278685] pwq 13: cpus=6 node=0 flags=0x0 nice=-20 active=1/256 refcnt=2
    >> |[ 20.279471] pending: blk_mq_requeue_work
    >> |[ 20.279989] pool 12: cpus=6 node=0 flags=0x0 nice=0 hung=5s workers=3 idle:
    >> | 535 42
    >>
    >> Another atempt. As you see `blk_mq_requeue_work' is references in both
    >> outputs but it makes progress (it is scheduled multiple times). The item
    >> `disk_events_workfn' stucks.
    >
    > I rebuilt kernel 5.6.4 with that patch, but before calling `shutdown -h
    > now' I guess I should have set printk_delay, because this time there was
    > a lot of output and it went by too fast. I'll try to delay it the next
    > time.

    I've done that now. I've sent you screenshots offlist. Here's a brief
    summary: The initial shutdown log output is essentially the same as the
    transcription I posted upthread, except that it is interspersed with
    messages from your patch like "Flush hid_reset+0x0/0x80". Then comes:

    ACPI: Preparing to enter system sleep state S5
    Flushing kacpid
    Flushing kacpid_notify
    Flushing kacpid_notify over, 0
    Showing busy workqueues and worker pools:
    workqueue events: flags=0x0
    pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: drm_fb_helper_diry_work
    workqueue kacpid_notify: flags=0x0
    pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/1 refcnt=4185
    in-flight: 1578:acpi_os_execute_deferred
    delayed: acpi_os_execute_deferred, acpi_os_execute_deferred, ...

    The "acpi_os_execute_deferred" messages were repeated many times in the
    above line, then every 20-30 seconds again for several minutes. Then
    suddenly a call trace appeared which was similar but not identical to
    the one I posted upthread, and each line of the trace was followed by
    the line ", acpi_os_execute_deferred". This went by quite quickly even
    with the printk_delay I added, and I was unable to photograph the start
    of it and couldn't get all of the subsequent output, but the screenshots
    show some of it. After several minutes of this output I again did a
    hard reboot.

    Steve Berman

    \
     
     \ /
      Last update: 2020-06-11 17:41    [W:2.602 / U:0.428 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site