Re: [PATCH] common: add printf debugging automation

[Jules Maselbas <jmaselbas@kalray.eu>]

Hi Ahmad,

On Sat, Mar 05, 2022 at 11:20:13PM +0100, Ahmad Fatoum wrote:
> This allows automating pinpointing of breakage outside PBL. For example
> if barebox is stuck during startup:
> 
>   - Turn on CONFIG_DEBUG_LL and CONFIG_DEBUG_INITCALLS
>   - Note last $initcall executed
By $initcall are you talking about the function name or about the
initcall address during startup ?

>   - Set CONFIG_FTRACE_CALLCHAIN=$initcall
>   - Serial output will stop at the last called traced function
> 
> Alternatively, enable CONFIG_FTRACE and stick tracing_on() somewhere.
> 
> Output will look like:
> 
>  [<4fd859a5>]   (netconsole_init+0x1/0x120) from [<4fd014c7>] (start_barebox+0x43/0x7c)
>  [<4fd77209>]     (xzalloc+0x1/0x34) from [<4fd859bd>] (netconsole_init+0x19/0x120)
>  [<4fd7719d>]       (xmalloc+0x1/0x34) from [<4fd77221>] (xzalloc+0x19/0x34)
>  [<4fd0995d>]         (malloc+0x1/0x54) from [<4fd771b5>] (xmalloc+0x19/0x34)
>  [<4fd0aae1>]           (tlsf_malloc+0x1/0x48) from [<4fd09983>] (malloc+0x27/0x54)
>  [<4fd0a1d9>]             (adjust_request_size+0x1/0x44) from [<4fd0aaff>] (tlsf_malloc+0x1f/0x48)
>  [<4fd0a18d>]               (align_up+0x1/0x4c) from [<4fd0a205>] (adjust_request_size+0x2d/0x44)
>  [<4fd0aa55>]             (block_locate_free+0x1/0x8c) from [<4fd0ab09>] (tlsf_malloc+0x29/0x48)
> 
> This is added as an experimental feature as it's not meant to be enabled
> at all time due to large overhead and may change considerably in future,
> e.g. to allow dumping to memory buffer and to record timestamps for
> profiling.
> 
> Signed-off-by: Ahmad Fatoum <a.fatoum@pengutronix.de>
> ---
>  Makefile           | 10 +++++-
>  common/Kconfig     | 15 +++++++++
>  include/ftrace.h   | 18 +++++++++++
>  lib/Makefile       |  4 +++
>  lib/ftrace.c       | 77 ++++++++++++++++++++++++++++++++++++++++++++++
>  lib/kasan/Makefile |  5 +++
>  6 files changed, 128 insertions(+), 1 deletion(-)
>  create mode 100644 include/ftrace.h
>  create mode 100644 lib/ftrace.c
> 
> diff --git a/Makefile b/Makefile
> index c04deaaa0f69..34743f4b6b45 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -469,7 +469,7 @@ export KBUILD_AFLAGS AFLAGS_KERNEL AFLAGS_MODULE
>  export KBUILD_AFLAGS_MODULE KBUILD_CFLAGS_MODULE
>  export KBUILD_AFLAGS_KERNEL KBUILD_CFLAGS_KERNEL
>  export LDFLAGS_barebox
> -export LDFLAGS_pbl
> +export LDFLAGS_pbl PBL_CPPFLAGS
>  
>  export CFLAGS_UBSAN
>  export CFLAGS_KASAN CFLAGS_KASAN_NOSANITIZE
> @@ -682,6 +682,14 @@ KBUILD_CFLAGS += $(call cc-option,-Wno-pointer-sign,)
>  # change __FILE__ to the relative path from the srctree
>  KBUILD_CFLAGS += $(call cc-option,-fmacro-prefix-map=$(srctree)/=)
>  
> +# The arch Makefiles can override CC_FLAGS_FTRACE. We may also append it later.
> +ifdef CONFIG_FTRACE
> +CC_FLAGS_FTRACE := -finstrument-functions
> +export CC_FLAGS_FTRACE
> +KBUILD_CFLAGS	+= $(CC_FLAGS_FTRACE)
> +PBL_CPPFLAGS   += -fno-instrument-functions
> +endif
> +
>  include-y +=scripts/Makefile.ubsan
>  include-$(CONFIG_KASAN)         += scripts/Makefile.kasan
>  
> diff --git a/common/Kconfig b/common/Kconfig
> index b8c3e34c0a58..2a35b43e2717 100644
> --- a/common/Kconfig
> +++ b/common/Kconfig
> @@ -1592,6 +1592,21 @@ config ASAN
>  	  Enables ASAN (AddressSANitizer) - runtime memory debugger,
>  	  designed to find out-of-bounds accesses and use-after-free bugs.
>  
> +config FTRACE
> +	bool "Enable function tracing (Only for debugging!)
missing closing quote here --------------------------------^
which generated the following warning when building:
common/Kconfig:1583:warning: multi-line strings not supported

> +	depends on EXPERIMENTAL
> +	help
> +	  This is not Linux-like ftrace, but a poor man's substitute using
> +	  GCC function instrumentation.
> +
> +config FTRACE_CALLCHAIN
> +	string "Print execution trace of all function below"
> +	depends on FTRACE && KALLSYMS
> +	default ""
> +	help
> +	  All functions called directly or indirectly by the specified
> +	  function will be logged to serial. Keep empty to disable
> +
>  config COMPILE_TEST
>  	bool "compile-test drivers of other platforms"
>  	default n
> diff --git a/include/ftrace.h b/include/ftrace.h
> new file mode 100644
> index 000000000000..68b46f1fa1d4
> --- /dev/null
> +++ b/include/ftrace.h
> @@ -0,0 +1,18 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _FTRACE_H__
> +#define _FTRACE_H__
> +
> +#ifdef CONFIG_FTRACE
> +void tracing_on(void);
> +void tracing_off(void);
> +#else
> +static inline void tracing_on(void)
> +{
> +}
> +static inline void tracing_off(void)
> +{
> +}
> +#endif
> +
> +#endif /* _FTRACE_H */
> diff --git a/lib/Makefile b/lib/Makefile
> index 3f6653d74e9a..7b86ad3383c3 100644
> --- a/lib/Makefile
> +++ b/lib/Makefile
> @@ -73,6 +73,7 @@ obj-$(CONFIG_CRC_CCITT) += crc-ccitt.o
>  obj-$(CONFIG_CRC8)	+= crc8.o
>  obj-$(CONFIG_NLS)	+= nls_base.o
>  obj-$(CONFIG_FSL_QE_FIRMWARE) += fsl-qe-firmware.o
> +obj-$(CONFIG_FTRACE)	+= ftrace.o
>  obj-$(CONFIG_UBSAN)	+= ubsan.o
>  
>  # GCC library routines
> @@ -85,6 +86,9 @@ pbl-$(CONFIG_GENERIC_LIB_ASHLDI3) += ashldi3.o
>  
>  UBSAN_SANITIZE_ubsan.o := n
>  
> +CFLAGS_REMOVE_ubsan.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_ftrace.o = $(CC_FLAGS_FTRACE)
> +
>  libfdt_files = fdt.o fdt_ro.o fdt_wip.o fdt_rw.o fdt_sw.o fdt_strerror.o \
>  	                      fdt_empty_tree.o
>  $(foreach file, $(libfdt_files), \
> diff --git a/lib/ftrace.c b/lib/ftrace.c
> new file mode 100644
> index 000000000000..1d0b36c10550
> --- /dev/null
> +++ b/lib/ftrace.c
> @@ -0,0 +1,77 @@
> +// SPDX-License-Identifier: GPL-2.0-or-later
> +
> +#include <common.h>
> +#include <clock.h>
> +#include <ftrace.h>
> +#include <kallsyms.h>
> +
> +static int trace_enabled __section(".data");
> +static volatile int trace_lock __section(".data");
> +static int depth __section(".data");
> +static const void *trigger __section(".data");
> +
> +void notrace tracing_on(void)
> +{
> +	if (trace_lock)
> +		return;
> +	trigger = NULL;
> +	trace_enabled = 1;
> +}
> +
> +void notrace tracing_off(void)
> +{
> +	if (trace_lock)
> +		return;
> +	trigger = NULL;
> +	trace_enabled = 0;
> +}
> +
> +void notrace __cyg_profile_func_enter(void *where, void *from)
> +{
> +	if (trace_lock)
> +		return;
> +
> +	if (trace_enabled <= 0) {
> +		if (where == trigger)
> +			trace_enabled++;
> +		else
> +			return;
> +	}
> +
> +	depth++;
> +
> +	trace_lock = true;
> +
> +	printf(" [<%08lx>] %*s(%pS) from [<%08lx>] (%pS)\n", (ulong) where,
> +	       depth * 2, "", where, (ulong)from, from);
> +
> +	trace_lock = false;
> +}
> +
> +void notrace __cyg_profile_func_exit(void *where, void *from)
> +{
> +	if (trace_lock || !trace_enabled)
> +		return;
> +
> +	depth--;
> +
> +	if (where == trigger)
> +		trace_enabled--;
> +}
> +
> +static int init_trace(void)
> +{
> +	ulong _trigger;
> +
> +	trace_lock = true;
> +
> +	_trigger = kallsyms_lookup_name(CONFIG_FTRACE_CALLCHAIN);
> +	if (IS_ENABLED(CONFIG_THUMB2_BAREBOX))
> +		_trigger |= 1;
> +	trigger = (void *)_trigger;
> +
> +	trace_lock = false;
> +
> +	return 0;
> +}
> +pure_initcall(init_trace);
> diff --git a/lib/kasan/Makefile b/lib/kasan/Makefile
> index e3f4bb61f900..06fa906ff620 100644
> --- a/lib/kasan/Makefile
> +++ b/lib/kasan/Makefile
> @@ -13,3 +13,8 @@ CFLAGS_generic_report.o := $(CC_FLAGS_KASAN_RUNTIME)
>  CFLAGS_generic.o := $(CC_FLAGS_KASAN_RUNTIME)
>  CFLAGS_report.o := $(CC_FLAGS_KASAN_RUNTIME)
>  CFLAGS_common.o := $(CC_FLAGS_KASAN_RUNTIME)
> +
> +CFLAGS_REMOVE_generic_report.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_generic.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_report.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_common.o = $(CC_FLAGS_FTRACE)
> -- 
> 2.30.2





_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox