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

[Joel Fernandes <joel@joelfernandes.org>]

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
>