diff mbox series

[RFC] ACPI: tracing: Have ACPI debug go to tracing ring buffer

Message ID 20221214233106.69b2c01b@gandalf.local.home
State New
Headers show
Series [RFC] ACPI: tracing: Have ACPI debug go to tracing ring buffer | expand

Commit Message

Steven Rostedt Dec. 15, 2022, 4:31 a.m. UTC 
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

While debugging some firmware that was taking a bit of time to initialize,
I enabled ACPI_DEBUG and added a bit too much info to the debug_layer and
debug_level acpi command line options, and it made the computer not be
able to boot (too much info! or too much printk).

I decided that this would be easier to handle if the acpi output was
written instead into the trace buffer. This also has the added benefit of
adding other trace events and seeing how ACPI interacts with the rest of
the system.

Ideally, the ACPI trace should have proper trace events where data can be
stored more efficiently and be filtered and parsed better. But for now,
just writing the debug string into the buffer will suffice.  This makes it
possible to enable all ACPI output (setting triggers on other events to
stop tracing, to not lose the data you are looking for).

Even with all APCI debugging enable, the system continues to run perfectly
fine.

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---

 drivers/acpi/Kconfig        | 13 +++++++++++++
 drivers/acpi/osl.c          |  9 ++++++++-
 include/trace/events/acpi.h | 30 ++++++++++++++++++++++++++++++
 3 files changed, 51 insertions(+), 1 deletion(-)
 create mode 100644 include/trace/events/acpi.h

Comments

Steven Rostedt Dec. 15, 2022, 7:11 p.m. UTC | #1 
On Thu, 15 Dec 2022 18:45:37 +0000
Joel Fernandes <joel@joelfernandes.org> wrote:

> Wouldn't it be better to also check trace_acpi_print_enabled() here in the
> else if() condition, along with IS_ENABLED()? That way if the CONFIG is
> enabled but the tracepoint is not enabled, at least the messages will go to
> dmesg instead of skipped.

I really don't want that. This was purposely done to be mutually exclusive.
The reason I added this in the first place, is because too much enabled
will render the system useless if printk() is used.

After boot up, if I had enabled all debug events and then I were to disable
the acpi tracepoint, it will likely render the system useless again if it
were to switch over to printk.

-- Steve
Joel Fernandes (Google) Dec. 15, 2022, 7:52 p.m. UTC | #2 
On Thu, Dec 15, 2022 at 2:11 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 15 Dec 2022 18:45:37 +0000
> Joel Fernandes <joel@joelfernandes.org> wrote:
>
> > Wouldn't it be better to also check trace_acpi_print_enabled() here in the
> > else if() condition, along with IS_ENABLED()? That way if the CONFIG is
> > enabled but the tracepoint is not enabled, at least the messages will go to
> > dmesg instead of skipped.
>
> I really don't want that. This was purposely done to be mutually exclusive.
> The reason I added this in the first place, is because too much enabled
> will render the system useless if printk() is used.
>
> After boot up, if I had enabled all debug events and then I were to disable
> the acpi tracepoint, it will likely render the system useless again if it
> were to switch over to printk.

Ok, sure. I see where you were going. So you want no debugging
messages at all if the trace event is disabled. That's fine with me. I
would also add a note about the need to enable the specific trace
event, in the Kconfig message and/or the Documentation. Otherwise, you
might get someone say, "hey I enabled the CONFIG option but I see
nothing in the trace buffer".

Another approach could be to always enable the trace event by default,
if the CONFIG is turned on. Or do a printk() telling the user about
the event to enable, so they know why their trace buffer is empty.

Up to you and the ACPI maintainers. ;-)

thanks,

 - Joel
Steven Rostedt Dec. 15, 2022, 8:13 p.m. UTC | #3 
On Thu, 15 Dec 2022 14:52:48 -0500
Joel Fernandes <joel@joelfernandes.org> wrote:

> Another approach could be to always enable the trace event by default,
> if the CONFIG is turned on. Or do a printk() telling the user about
> the event to enable, so they know why their trace buffer is empty.

Yeah, that is another option.

And, yes I need to document it better. I started to, but then decided to
hold off until I get some feedback in case this is rejected.

> 
> Up to you and the ACPI maintainers. ;-)

I'm going to guess I may not hear back until the new year. I'm fine with
that :-) I'll send a reminder then too as I Cc'd the linux-trace-kernel
list, which will keep it active in patchwork.

Cheers!

-- Steve
Rafael J. Wysocki Dec. 30, 2022, 3:52 p.m. UTC | #4 
On Thu, Dec 15, 2022 at 9:13 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 15 Dec 2022 14:52:48 -0500
> Joel Fernandes <joel@joelfernandes.org> wrote:
>
> > Another approach could be to always enable the trace event by default,
> > if the CONFIG is turned on. Or do a printk() telling the user about
> > the event to enable, so they know why their trace buffer is empty.
>
> Yeah, that is another option.
>
> And, yes I need to document it better. I started to, but then decided to
> hold off until I get some feedback in case this is rejected.
>
> >
> > Up to you and the ACPI maintainers. ;-)
>
> I'm going to guess I may not hear back until the new year. I'm fine with
> that :-)

It's just a couple of days, but still.

Personally, I would use a command line option to control the behavior
and the Kconfig option to provide its default value.

This way it can be flipped without rebuilding the kernel if need be.

I would also make the ACPI debug output go into the trace buffer so
long as the Kconfig option is not changed or the command line option
is not flipped.

Cheers!
Steven Rostedt Jan. 4, 2023, 9:39 p.m. UTC | #5 
On Fri, 30 Dec 2022 16:52:36 +0100
"Rafael J. Wysocki" <rafael@kernel.org> wrote:

> Personally, I would use a command line option to control the behavior
> and the Kconfig option to provide its default value.
> 

I can add that.

> This way it can be flipped without rebuilding the kernel if need be.
> 
> I would also make the ACPI debug output go into the trace buffer so
> long as the Kconfig option is not changed or the command line option
> is not flipped.

Not sure what you mean by the above? You mean to make going to both as the
default?

-- Steve
Rafael J. Wysocki Jan. 5, 2023, 2:55 p.m. UTC | #6 
On Wed, Jan 4, 2023 at 10:39 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 30 Dec 2022 16:52:36 +0100
> "Rafael J. Wysocki" <rafael@kernel.org> wrote:
>
> > Personally, I would use a command line option to control the behavior
> > and the Kconfig option to provide its default value.
> >
>
> I can add that.
>
> > This way it can be flipped without rebuilding the kernel if need be.
> >
> > I would also make the ACPI debug output go into the trace buffer so
> > long as the Kconfig option is not changed or the command line option
> > is not flipped.
>
> Not sure what you mean by the above? You mean to make going to both as the
> default?

No, just send them to the trace buffer alone unless specifically told
to printk() them.
diff mbox series

Patch

diff --git a/drivers/acpi/Kconfig b/drivers/acpi/Kconfig
index 473241b5193f..2dfeb3bf79a7 100644
--- a/drivers/acpi/Kconfig
+++ b/drivers/acpi/Kconfig
@@ -389,6 +389,19 @@  config ACPI_DEBUG
 	  Documentation/admin-guide/kernel-parameters.rst to control the type and
 	  amount of debug output.
 
+config ACPI_TRACE_PRINT
+	bool "Write debug into trace buffer"
+	depends on ACPI_DEBUG
+	help
+	  Instead of writing to the console, write to the trace ring buffer.
+	  This is much faster than writing to the console, and can handle
+	  all events.
+
+	  Use the acpi.debug_layer and acpi.debug_level kernel command-line
+	  parameters documented in Documentation/firmware-guide/acpi/debug.rst and
+	  Documentation/admin-guide/kernel-parameters.rst to control the type and
+	  amount of debug output.
+
 config ACPI_PCI_SLOT
 	bool "PCI slot detection driver"
 	depends on SYSFS && PCI
diff --git a/drivers/acpi/osl.c b/drivers/acpi/osl.c
index 3269a888fb7a..eeed5fd782ab 100644
--- a/drivers/acpi/osl.c
+++ b/drivers/acpi/osl.c
@@ -35,6 +35,9 @@ 
 #include <linux/uaccess.h>
 #include <linux/io-64-nonatomic-lo-hi.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/acpi.h>
+
 #include "acpica/accommon.h"
 #include "internal.h"
 
@@ -158,6 +161,8 @@  void acpi_os_vprintf(const char *fmt, va_list args)
 #ifdef ENABLE_DEBUGGER
 	if (acpi_in_debugger) {
 		kdb_printf("%s", buffer);
+	} else if (IS_ENABLED(CONFIG_ACPI_TRACE_PRINT)) {
+		trace_acpi_print(buffer);
 	} else {
 		if (printk_get_level(buffer))
 			printk("%s", buffer);
@@ -165,7 +170,9 @@  void acpi_os_vprintf(const char *fmt, va_list args)
 			printk(KERN_CONT "%s", buffer);
 	}
 #else
-	if (acpi_debugger_write_log(buffer) < 0) {
+	if (IS_ENABLED(CONFIG_ACPI_TRACE_PRINT)) {
+		trace_acpi_print(buffer);
+	} else if (acpi_debugger_write_log(buffer) < 0) {
 		if (printk_get_level(buffer))
 			printk("%s", buffer);
 		else
diff --git a/include/trace/events/acpi.h b/include/trace/events/acpi.h
new file mode 100644
index 000000000000..dab4dd42b5d7
--- /dev/null
+++ b/include/trace/events/acpi.h
@@ -0,0 +1,30 @@ 
+/* SPDX-License-Identifier: GPL-2.0+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM acpi
+
+#if !defined(_TRACE_ACPI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_ACPI_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(acpi_print,
+
+	TP_PROTO(const char *buffer),
+
+	TP_ARGS(buffer),
+
+	TP_STRUCT__entry(
+		__string(buffer, buffer)
+	),
+
+	TP_fast_assign(
+		__assign_str(buffer, buffer);
+	),
+
+	TP_printk("%s", __get_str(buffer))
+);
+
+#endif /* _TRACE_SOCK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>