mail archive of the barebox mailing list
 help / color / mirror / Atom feed
* [PATCH] common: add printf debugging automation
@ 2022-03-05 22:20 Ahmad Fatoum
  2022-03-06 22:49 ` Jules Maselbas
  0 siblings, 1 reply; 3+ messages in thread
From: Ahmad Fatoum @ 2022-03-05 22:20 UTC (permalink / raw)
  To: barebox; +Cc: Jules Maselbas, Ahmad Fatoum

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
  - 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!)
+	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


^ permalink raw reply	[flat|nested] 3+ messages in thread
* Re: [PATCH] common: add printf debugging automation
  2022-03-05 22:20 [PATCH] common: add printf debugging automation Ahmad Fatoum
@ 2022-03-06 22:49 ` Jules Maselbas
  2022-03-07 17:06   ` Ahmad Fatoum
  0 siblings, 1 reply; 3+ messages in thread
From: Jules Maselbas @ 2022-03-06 22:49 UTC (permalink / raw)
  To: Ahmad Fatoum; +Cc: barebox

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


^ permalink raw reply	[flat|nested] 3+ messages in thread
* Re: [PATCH] common: add printf debugging automation
  2022-03-06 22:49 ` Jules Maselbas
@ 2022-03-07 17:06   ` Ahmad Fatoum
  0 siblings, 0 replies; 3+ messages in thread
From: Ahmad Fatoum @ 2022-03-07 17:06 UTC (permalink / raw)
  To: Jules Maselbas; +Cc: barebox

Hello Jules,

On 06.03.22 23:49, Jules Maselbas wrote:
> 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 ?

Function name, that's why KALLSYMS is required. It's not strictly necessary
though and code could just check if the first character is a digit and accept
an address in that case. I will do this for v2.

>> 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

Thanks, will fix for v2.

Cheers,
Ahmad


-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

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


^ permalink raw reply	[flat|nested] 3+ messages in thread
end of thread, other threads:[~2022-03-07 17:07 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-03-05 22:20 [PATCH] common: add printf debugging automation Ahmad Fatoum
2022-03-06 22:49 ` Jules Maselbas
2022-03-07 17:06   ` Ahmad Fatoum

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox