Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Stephen Berman <stephen.berman@gmx.net>
To:     Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Cc:     Thomas Gleixner <tglx@linutronix.de>,
        Peter Zijlstra <peterz@infradead.org>,
        linux-kernel@vger.kernel.org, linux-acpi@vger.kernel.org
Subject: Re: power-off delay/hang due to commit 6d25be57 (mainline)
References: <87y2owwo2o.fsf@rub.de>
        <20200609202339.cgy57twm2zdtjhje@linutronix.de>
        <87tuzjcovq.fsf@gmx.net>
        <20200610102514.4vdzu5u7d6vnpicn@linutronix.de>
        <87imfyh6yx.fsf@gmx.net> <87wo4dligz.fsf@gmx.net>
        <20200612110122.jossn5zrktcvpbpm@linutronix.de>
        <87tuzdrgm5.fsf@gmx.net>
        <20200614171005.3zy673p6bpwoqnmq@linutronix.de>
        <874krcsquv.fsf@gmx.net>
        <20200615145130.bcdidqkp6w23xb6c@linutronix.de>
Date:   Mon, 15 Jun 2020 17:41:06 +0200
In-Reply-To: <20200615145130.bcdidqkp6w23xb6c@linutronix.de> (Sebastian
        Andrzej Siewior's message of "Mon, 15 Jun 2020 16:51:30 +0200")
Message-ID: <87tuzcqqul.fsf@gmx.net>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.0.50 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Mon, 15 Jun 2020 16:51:30 +0200 Sebastian Andrzej Siewior <bigeasy@linut=
ronix.de> wrote:

> 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.

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'?

>> 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 runtim=
e,
>> > 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=E2=80=A6
>>=20
>> 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=20
>   acpi_os_execute(1109) Adding acpi_ev_notify_dispatch" messages?
> No
>   "acpi_os_execute_deferred_notify() Start/End acpi_ev_notify_dispatch"?=
=20
>
> The syslog should have captured the log on disk.

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:

Jun 15 08:58:25 strobe-jhalfs kernel: [  193.315014] acpi_os_execute(1109) =
Adding acpi_ev_notify_dispatch+0x0/0x55 ffff8d7aa99a66e0 <ffff8d7aabb38480>
Jun 15 08:58:25 strobe-jhalfs kernel: [  193.319929] acpi_os_execute_deferr=
ed_notify(853) End   ffff8d7aa8758d00 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e7eb0)
Jun 15 08:58:25 strobe-jhalfs kernel: [  193.321242] acpi_os_execute_deferr=
ed_notify(851) Start ffff8d7aa8758a80 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e70a0)
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_deferr=
ed_notify(853) End   ffff8d7aa8758a80 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e70a0)
Jun 15 08:58:27 strobe-jhalfs kernel: [  195.369234] acpi_os_execute_deferr=
ed_notify(851) Start ffff8d7aa8758240 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e7a00)
Jun 15 08:58:28 strobe-jhalfs kernel: [  196.387017] acpi_os_execute(1109) =
Adding acpi_ev_notify_dispatch+0x0/0x55 ffff8d7aa99a68c0 <ffff8d7aabb38540>
Jun 15 08:58:28 strobe-jhalfs kernel: [  196.388508] acpi_os_execute_deferr=
ed_notify(853) End   ffff8d7aa8758240 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e7a00)
Jun 15 08:58:28 strobe-jhalfs kernel: [  196.390128] acpi_os_execute_deferr=
ed_notify(851) Start ffff8d7aa8758b80 acpi_ev_notify_dispatch+0x0/0x55(ffff=
8d7aa84e7460)
Jun 15 08:58:29 strobe-jhalfs kernel: [  197.208714] wlan1: deauthenticatin=
g from 7c:ff:4d:08:df:22 by local choice (Reason: 3=3DDEAUTH_LEAVING)
Jun 15 08:58:29 strobe-jhalfs kernel: [  197.232214] ip (4614) used greates=
t stack depth: 11272 bytes left
Jun 15 08:58:29 strobe-jhalfs kernel: Kernel logging (proc) stopped.
Jun 15 08:58:29 strobe-jhalfs kernel: Kernel log daemon terminating.

> I attached a modified acpi_dbg.patch. Please enable:
> - CONFIG_ACPI_DEBUG=3Dy
>
> 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.

Will do as soon as I can, hopefully later today or tomorrow.  Thanks.

Steve Berman