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)
Date: Mon, 15 Jun 2020 17:41:06 +0200 [thread overview]
Message-ID: <87tuzcqqul.fsf@gmx.net> (raw)
In-Reply-To: <20200615145130.bcdidqkp6w23xb6c@linutronix.de> (Sebastian Andrzej Siewior's message of "Mon, 15 Jun 2020 16:51:30 +0200")
On Mon, 15 Jun 2020 16:51:30 +0200 Sebastian Andrzej Siewior <bigeasy@linutronix.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 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.
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_deferred_notify(853) End ffff8d7aa8758d00 acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e7eb0)
Jun 15 08:58:25 strobe-jhalfs kernel: [ 193.321242] 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 acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e70a0)
Jun 15 08:58:27 strobe-jhalfs kernel: [ 195.369234] acpi_os_execute_deferred_notify(851) Start ffff8d7aa8758240 acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e7a00)
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_deferred_notify(853) End ffff8d7aa8758240 acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e7a00)
Jun 15 08:58:28 strobe-jhalfs kernel: [ 196.390128] acpi_os_execute_deferred_notify(851) Start ffff8d7aa8758b80 acpi_ev_notify_dispatch+0x0/0x55(ffff8d7aa84e7460)
Jun 15 08:58:29 strobe-jhalfs kernel: [ 197.208714] wlan1: deauthenticating from 7c:ff:4d:08:df:22 by local choice (Reason: 3=DEAUTH_LEAVING)
Jun 15 08:58:29 strobe-jhalfs kernel: [ 197.232214] ip (4614) used greatest 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=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.
Will do as soon as I can, hopefully later today or tomorrow. Thanks.
Steve Berman
next prev parent reply other threads:[~2020-06-15 15:41 UTC|newest]
Thread overview: 42+ messages / expand[flat|nested] mbox.gz Atom feed top
[not found] <87v9l65d2y.fsf@gmx.net>
[not found] ` <20200513220428.4nksinis2qs5dtmh@linutronix.de>
[not found] ` <87mu6aurfn.fsf@gmx.net>
[not found] ` <20200522164012.ynyvrjompv42jtmx@linutronix.de>
[not found] ` <87y2owwo2o.fsf@rub.de>
[not found] ` <20200609202339.cgy57twm2zdtjhje@linutronix.de>
[not found] ` <87tuzjcovq.fsf@gmx.net>
[not found] ` <20200610102514.4vdzu5u7d6vnpicn@linutronix.de>
[not found] ` <87imfyh6yx.fsf@gmx.net>
[not found] ` <87wo4dligz.fsf@gmx.net>
2020-06-12 11:01 ` power-off delay/hang due to commit 6d25be57 (mainline) Sebastian Andrzej Siewior
2020-06-14 12:12 ` Stephen Berman
2020-06-14 17:10 ` Sebastian Andrzej Siewior
2020-06-15 7:58 ` Stephen Berman
2020-06-15 14:51 ` Sebastian Andrzej Siewior
2020-06-15 15:41 ` Stephen Berman [this message]
2020-06-15 15:58 ` Sebastian Andrzej Siewior
2020-06-15 16:19 ` Stephen Berman
2020-06-15 16:32 ` Sebastian Andrzej Siewior
2020-06-16 7:14 ` Stephen Berman
2020-06-16 7:38 ` Sebastian Andrzej Siewior
2020-06-16 8:13 ` Stephen Berman
2020-06-16 15:55 ` Sebastian Andrzej Siewior
2020-06-16 20:28 ` Stephen Berman
2020-06-17 14:27 ` Sebastian Andrzej Siewior
2020-06-17 21:09 ` Stephen Berman
2020-06-24 20:11 ` Sebastian Andrzej Siewior
2020-06-24 21:49 ` Stephen Berman
2020-07-14 13:44 ` Sebastian Andrzej Siewior
2020-07-14 13:54 ` Rafael J. Wysocki
2020-07-14 14:11 ` Sebastian Andrzej Siewior
2020-07-14 15:53 ` Rafael J. Wysocki
2020-07-14 16:10 ` Sebastian Andrzej Siewior
2020-08-11 10:27 ` Sebastian Andrzej Siewior
2020-08-11 14:02 ` Rafael J. Wysocki
2020-07-19 10:07 ` Stephen Berman
2020-08-11 11:58 ` Stephen Berman
2020-08-11 13:29 ` Sebastian Andrzej Siewior
2020-08-11 14:34 ` Rafael J. Wysocki
2020-08-11 15:25 ` Sebastian Andrzej Siewior
[not found] ` <87ft8tayic.fsf@gmx.net>
2020-08-11 18:49 ` Sebastian Andrzej Siewior
2020-10-06 21:49 ` Sebastian Andrzej Siewior
2020-10-07 16:18 ` Rafael J. Wysocki
2020-10-26 17:20 ` Sebastian Andrzej Siewior
2020-12-02 18:03 ` Sebastian Andrzej Siewior
2020-12-02 18:31 ` Rafael J. Wysocki
2020-12-02 19:13 ` Rafael J. Wysocki
2020-12-31 20:46 ` Rafael J. Wysocki
2021-01-02 11:03 ` Rafael J. Wysocki
2021-01-04 15:38 ` Stephen Berman
2021-01-24 13:49 ` Stephen Berman
2021-01-25 16:25 ` Rafael J. Wysocki
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=87tuzcqqul.fsf@gmx.net \
--to=stephen.berman@gmx.net \
--cc=bigeasy@linutronix.de \
--cc=linux-acpi@vger.kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=peterz@infradead.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).