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 16:51:30 +0200
From:   Sebastian Andrzej Siewior <bigeasy@...utronix.de>
To:     Stephen Berman <stephen.berman@....net>
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 2020-06-15 09:58:00 [+0200], Stephen Berman wrote:
> Ok, sorry, I had misunderstood, but now I've looked at the
> documentation.  I had in fact already done `echo t >
> /proc/sysrq-trigger' in an xterm (as root) and there was no output.
> Later, after booting kernel 5.1.0 because of the message flooding with
> 5.6.4, I did `echo t > /proc/sysrq-trigger' in a virtual tty (also as
> root) and the only output was: `[ <timestamp>] sysrq: Show State'.  Is
> this expected?  (In /proc/sys/kernel/sysrq there is `1'.)  I couldn't
> try it in a 5.6.4 virtual tty because of the message flooding (see
> below).

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.

> The kernel log shows 305 of these messages in the 4 minutes and 17
> seconds between the start of klogd and when I rebooted.

Okay, this is a lot.

> > The interesting part is to see if there is a acpi_os_execute() adding a
> > specific event multiple times which does not complete. Maybe at runtime,
> > maybe at shutdown time. If that is the case then ignoring this specific
> > event might fix the shutdown problem. With all this information so far,
> > I don't see a relation with this problem and the commit…
> 
> In those 3 minutes and 8 seconds there were 5 "Adding
> acpi_ev_asynch_enable_gpe" messages at the beginning, then 185 "Adding
> acpi_ev_notify_dispatch" messages, which kept coming until I rebooted.

5 acpi_ev_asynch_enable_gpe() in three minutes since boot isn't much.
185 of "Adding acpi_ev_notify_dispatch" is a lot.

But to be clear, only 
  acpi_os_execute(1109) Adding acpi_ev_notify_dispatch" messages?
No
  "acpi_os_execute_deferred_notify() Start/End acpi_ev_notify_dispatch"? 

The syslog should have captured the log on disk.

I attached a modified acpi_dbg.patch. Please enable:
- CONFIG_ACPI_DEBUG=y

Looking at your 5.1 you have tracing enabled (hope it still is).

The attached patch will dump the date into the tracing buffer, so you
console should remain "clean". Once it records 300 of those "requests
for acpi_ev_notify_dispatch" it will stop recording.
After 4-5 minutes please do
	cat /sys/kernel/debug/tracing/trace > file.txt

compress it and send it.

> Steve Berman

Sebastian

View attachment "acpi_dbg.patch" of type "text/x-diff" (3544 bytes)