linux-kernel - Re: power-off delay/hang due to commit 6d25be57 (mainline)

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Mon, 15 Jun 2020 18:19:18 +0200
From:   Stephen Berman <stephen.berman@....net>
To:     Sebastian Andrzej Siewior <bigeasy@...utronix.de>
Cc:     Thomas Gleixner <tglx@...utronix.de>,
        Peter Zijlstra <peterz@...radead.org>,
        linux-kernel@...r.kernel.org, linux-acpi@...r.kernel.org
Subject: Re: power-off delay/hang due to commit 6d25be57 (mainline)

On Mon, 15 Jun 2020 17:58:46 +0200 Sebastian Andrzej Siewior <bigeasy@...utronix.de> wrote:

> On 2020-06-15 17:41:06 [+0200], Stephen Berman wrote:
>> > If you do this "t" then there should be a lot of output on your console.
>> > If you do this from an xterm then you can see the output after typing
>> > "dmesg". The output should appear also in your system log.
>> 
>> Ah, ok, I do see it in the log, it looks basically the same as the call
>> trace I posted upthread.  I wonder why there was no such output in the
>> console, could there be some setting that suppresses it even though
>> /proc/sys/kernel/sysrq has `1'?
>
> You have ignore_loglevel soo everything should appear on your console.
> The is true for your tty / ctrl+alt+f1 but your xterm shell.

Yet that appears not to be the case here, or I'm still doing something
wrong 🤷

>> There were in fact 99 "Start .* acpi_ev_notify_dispatch" messages and 98
>> "End .* acpi_ev_notify_dispatch" messages.  Here's the last of them
>> before I rebooted:
[...] 
>> acpi_os_execute_deferred_notify(851) Start ffff8d7aa8758a80
>> acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e70a0)
>> Jun 15 08:58:26 strobe-jhalfs kernel: [ 194.339017] acpi_os_execute(1109)
>> Adding acpi_ev_notify_dispatch+0x0/0x55 ffff8d7aa99a6730 <ffff8d7aabb384c0>
>> Jun 15 08:58:27 strobe-jhalfs kernel: [ 195.363005] acpi_os_execute(1109)
>> Adding acpi_ev_notify_dispatch+0x0/0x55 ffff8d7aa99a6780 <ffff8d7aabb38500>
>> Jun 15 08:58:27 strobe-jhalfs kernel: [ 195.367978]
>> acpi_os_execute_deferred_notify(853) End ffff8d7aa8758a80
[...] 

> Okay. So there is "Adding" of four events/work items in total, each
> almost every second.
> Processing of one work-item took two seconds, the other one took a
> second. These events are "old" so I don't see the "adding" line for the
> Start/End.
> You could look in the log for ffff8d7aa8758a80 to seen when it was
> enqueued but it feels like ACPI enqueues more events then it is capable
> of processing.

It's there, 196 lines above the Start ffff8d7aa8758a80 line:

Jun 15 08:56:58 strobe-jhalfs kernel: [  106.275356] acpi_os_execute(1109) Adding acpi_ev_notify_dispatch+0x0/0x55 ffff8d7aa84e70a0 <ffff8d7aa8758a80>

Steve Berman