| Message ID | 20221214233106.69b2c01b@gandalf.local.home (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [RFC] ACPI: tracing: Have ACPI debug go to tracing ring buffer | expand |
Hi Steve, On Wed, Dec 14, 2022 at 11:31:06PM -0500, Steven Rostedt wrote: > 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 > > 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); 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. > } 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) { Ditto. Reviewed-by: Joel Fernandes (Google) <joel@joelfernandes.org> thanks, - Joel > 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> > -- > 2.35.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
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
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
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!
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
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 --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>