From e38cdc684b6fd47d9ca133ac5b50773f7b0d0142 Mon Sep 17 00:00:00 2001 From: Tom Rini Date: Tue, 7 Feb 2023 12:50:13 -0500 Subject: Dockerfile: Update QEMU git location Per https://www.qemu.org/contribute/ the official location of the QEMU sources are https://gitlab.com/qemu-project/qemu.git Reviewed-by: Simon Glass Signed-off-by: Tom Rini --- tools/docker/Dockerfile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/docker/Dockerfile b/tools/docker/Dockerfile index 202a8145af7..3d5a9a07447 100644 --- a/tools/docker/Dockerfile +++ b/tools/docker/Dockerfile @@ -173,7 +173,7 @@ RUN git clone git://git.savannah.gnu.org/grub.git /tmp/grub && \ true && \ rm -rf /tmp/grub -RUN git clone git://git.qemu.org/qemu.git /tmp/qemu && \ +RUN git clone https://gitlab.com/qemu-project/qemu.git /tmp/qemu && \ cd /tmp/qemu && \ git submodule update --init dtc && \ git checkout v6.1.0 && \ -- cgit v1.3.1 From 41cd6fab03af8f1d3fae6ee04937583ab7884efa Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:38 -0700 Subject: .gitignore: Ignore the moveconfig database This file is produced by the moveconfig.py tool. It should never be added to the repo, so add it to the .gitignore file. Signed-off-by: Simon Glass --- .gitignore | 3 +++ 1 file changed, 3 insertions(+) diff --git a/.gitignore b/.gitignore index 3adf1faf4e7..3a4d056edfc 100644 --- a/.gitignore +++ b/.gitignore @@ -105,3 +105,6 @@ __pycache__ # pylint files /pylint.cur /pylint.out/ + +# moveconfig database +/moveconfig.db -- cgit v1.3.1 From 2c88d5e110517ba7565b33eb8bfabb0ae0885eab Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:40 -0700 Subject: sandbox: Bring back setting mon_len in global_data This change was made for the benefit of RISC-V but broke other architectures also. In particular, tracing cannot work without this value. Add it back for architectures which support it. Fixes: 3c9fc23c443 ("sandbox: don't refer to symbol _init") Signed-off-by: Simon Glass --- common/board_f.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/common/board_f.c b/common/board_f.c index 2b4edf30c93..f3c1ab53b1c 100644 --- a/common/board_f.c +++ b/common/board_f.c @@ -290,7 +290,10 @@ static int setup_mon_len(void) { #if defined(__ARM__) || defined(__MICROBLAZE__) gd->mon_len = (ulong)&__bss_end - (ulong)_start; +#elif defined(CONFIG_SANDBOX) && !defined(__riscv) + gd->mon_len = (ulong)&_end - (ulong)_init; #elif defined(CONFIG_SANDBOX) + /* gcc does not provide _init in crti.o on RISC-V */ gd->mon_len = 0; #elif defined(CONFIG_EFI_APP) gd->mon_len = (ulong)&_end - (ulong)_init; -- cgit v1.3.1 From c38a21d7199b2e34af2d161fc58674ec81b2105d Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:41 -0700 Subject: dm: Allow serial output during the relocation process Reset the serial flags so that the debug UART can be used (if enabled) in the small window where there is no serial device. This can avoid a hang in some cases. Signed-off-by: Simon Glass --- common/board_r.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/common/board_r.c b/common/board_r.c index c6c0c1ab1d9..e45003353f7 100644 --- a/common/board_r.c +++ b/common/board_r.c @@ -796,6 +796,15 @@ static init_fnc_t init_sequence_r[] = { void board_init_r(gd_t *new_gd, ulong dest_addr) { + /* + * The pre-relocation drivers may be using memory that has now gone + * away. Mark serial as unavailable - this will fall back to the debug + * UART if available. + * + * Do the same with log drivers since the memory may not be available. + */ + gd->flags &= ~(GD_FLG_SERIAL_READY | GD_FLG_LOG_READY); + /* * Set up the new global data pointer. So far only x86 does this * here. -- cgit v1.3.1 From 4aa5053da5fa0729d30bce5df9a0a037a391f2f3 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:42 -0700 Subject: timer: Tidy up use of notrace Tracing is typically enabled by the time driver model starts up, so there is no point in adding a 'notrace' to the timer-init function. However, once the driver model timer is enabled, we do need to be able to access the timer's private data when reading the timer, so add it to the core function needed for that. Update the function's documentation while we are here. Signed-off-by: Simon Glass --- drivers/core/device.c | 3 ++- drivers/timer/timer-uclass.c | 2 +- include/timer.h | 13 +++++++++---- 3 files changed, 12 insertions(+), 6 deletions(-) diff --git a/drivers/core/device.c b/drivers/core/device.c index d9ce546c0c4..6e26b64fb81 100644 --- a/drivers/core/device.c +++ b/drivers/core/device.c @@ -654,7 +654,8 @@ void *dev_get_priv(const struct udevice *dev) return dm_priv_to_rw(dev->priv_); } -void *dev_get_uclass_priv(const struct udevice *dev) +/* notrace is needed as this is called by timer_get_rate() */ +notrace void *dev_get_uclass_priv(const struct udevice *dev) { if (!dev) { dm_warn("%s: null device\n", __func__); diff --git a/drivers/timer/timer-uclass.c b/drivers/timer/timer-uclass.c index bb719792135..f4b871ac23a 100644 --- a/drivers/timer/timer-uclass.c +++ b/drivers/timer/timer-uclass.c @@ -136,7 +136,7 @@ u64 timer_conv_64(u32 count) return ((u64)gd->timebase_h << 32) | gd->timebase_l; } -int notrace dm_timer_init(void) +int dm_timer_init(void) { struct udevice *dev = NULL; __maybe_unused ofnode node; diff --git a/include/timer.h b/include/timer.h index d33a26e28fe..311ce6b2c3a 100644 --- a/include/timer.h +++ b/include/timer.h @@ -9,11 +9,16 @@ #define timer_get_ops(dev) ((struct timer_ops *)(dev)->driver->ops) /** - * dm_timer_init() - initialize a timer for time keeping. On success - * initializes gd->timer so that lib/timer can use it for future - * referrence. + * dm_timer_init() - set up a timer for time keeping * - * Return: 0 on success or error number + * Sets up gd->timer if the device is not already bound, making sure it is + * probed and ready for use + * + * On success, inits gd->timer so that lib/timer can use it for future reference + * + * Returns: 0 on success, -EAGAIN if driver model is not ready yet, -ENODEV if + * no timer could be found, other error if the timer could not be bound or + * probed */ int dm_timer_init(void); -- cgit v1.3.1 From 64d445a3b7018dac5131cba9f5d308c64a45e95f Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:43 -0700 Subject: time: Tidy up some unnecessary #ifdefs Avoid using the preprocessor with TIMER_EARLY. Signed-off-by: Simon Glass --- lib/time.c | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/lib/time.c b/lib/time.c index 5252190af53..00f4a1ac8fb 100644 --- a/lib/time.c +++ b/lib/time.c @@ -70,15 +70,14 @@ extern unsigned long timer_read_counter(void); ulong notrace get_tbclk(void) { if (!gd->timer) { -#ifdef CONFIG_TIMER_EARLY - return timer_early_get_rate(); -#else int ret; + if (IS_ENABLED(CONFIG_TIMER_EARLY)) + return timer_early_get_rate(); + ret = dm_timer_init(); if (ret) return ret; -#endif } return timer_get_rate(gd->timer); @@ -90,15 +89,14 @@ uint64_t notrace get_ticks(void) int ret; if (!gd->timer) { -#ifdef CONFIG_TIMER_EARLY - return timer_early_get_count(); -#else int ret; + if (IS_ENABLED(CONFIG_TIMER_EARLY)) + return timer_early_get_count(); + ret = dm_timer_init(); if (ret) panic("Could not initialize timer (err %d)\n", ret); -#endif } ret = timer_get_count(gd->timer, &count); -- cgit v1.3.1 From c33425c6f960944ba88104f281217de5a89a5562 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:44 -0700 Subject: trace: Reduce the default for TRACE_EARLY_CALL_DEPTH_LIMIT This is a silly value at present, since U-Boot's call depth never reaches 200. Fix it. Signed-off-by: Simon Glass --- lib/Kconfig | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/Kconfig b/lib/Kconfig index 06c873c2bd2..83e5edd73b0 100644 --- a/lib/Kconfig +++ b/lib/Kconfig @@ -368,7 +368,7 @@ config TRACE_EARLY_SIZE config TRACE_EARLY_CALL_DEPTH_LIMIT int "Early trace call depth limit" depends on TRACE_EARLY - default 200 + default 15 help Sets the maximum call depth up to which function calls are recorded during early tracing. -- cgit v1.3.1 From 90ad4e28e8d299395922364409c37bd7afc293e4 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:45 -0700 Subject: abuf: Support use from tools Update the code slightly so that abuf can be used in U-Boot tools. It will soon be needed for proftool. Signed-off-by: Simon Glass --- lib/abuf.c | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/lib/abuf.c b/lib/abuf.c index 1635d58682c..bd270467dd4 100644 --- a/lib/abuf.c +++ b/lib/abuf.c @@ -6,11 +6,14 @@ * Written by Simon Glass */ +#ifndef USE_HOSTCC #include -#include #include #include #include +#endif + +#include void abuf_set(struct abuf *abuf, void *data, size_t size) { @@ -19,10 +22,26 @@ void abuf_set(struct abuf *abuf, void *data, size_t size) abuf->size = size; } +#ifndef USE_HOSTCC void abuf_map_sysmem(struct abuf *abuf, ulong addr, size_t size) { abuf_set(abuf, map_sysmem(addr, size), size); } +#else +/* copied from lib/string.c for convenience */ +static char *memdup(const void *src, size_t len) +{ + char *p; + + p = malloc(len); + if (!p) + return NULL; + + memcpy(p, src, len); + + return p; +} +#endif bool abuf_realloc(struct abuf *abuf, size_t new_size) { -- cgit v1.3.1 From d9044e5363bb0b32a7aff00adf47c227f78f0f32 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:46 -0700 Subject: trace: Update the file header It seems better to put the TEXT_BASE value in the file header rather than in an entry record. While it is true that there is a separate base for pre-relocation, this can be handled by using offsets in the file. It is useful to have a version number in case we need to change the trace format again. Update the header to make these changes. Signed-off-by: Simon Glass --- include/trace.h | 12 ++++++++++-- lib/trace.c | 19 ++++--------------- 2 files changed, 14 insertions(+), 17 deletions(-) diff --git a/include/trace.h b/include/trace.h index e7aee024f03..2be8d81b515 100644 --- a/include/trace.h +++ b/include/trace.h @@ -6,6 +6,8 @@ #ifndef __TRACE_H #define __TRACE_H +/* this file is included from a tool so uses uint32_t instead of u32, etc. */ + enum { /* * This affects the granularity of our trace. We can bin function @@ -23,6 +25,8 @@ enum { * this value. */ FUNC_SITE_SIZE = 4, /* distance between function sites */ + + TRACE_VERSION = 1, }; enum trace_chunk_type { @@ -39,7 +43,11 @@ struct trace_output_func { /* A header at the start of the trace output buffer */ struct trace_output_hdr { enum trace_chunk_type type; /* Record type */ - size_t rec_count; /* Number of records */ + uint32_t version; /* Version (TRACE_VERSION) */ + uint32_t rec_count; /* Number of records */ + uint32_t spare; /* 0 */ + uint64_t text_base; /* Value of CONFIG_TEXT_BASE */ + uint64_t spare2; /* 0 */ }; /* Print statistics about traced function calls */ @@ -63,7 +71,7 @@ int trace_list_functions(void *buff, size_t buff_size, size_t *needed); enum ftrace_flags { FUNCF_EXIT = 0UL << 30, FUNCF_ENTRY = 1UL << 30, - FUNCF_TEXTBASE = 2UL << 30, + /* two more values are available */ FUNCF_TIMESTAMP_MASK = 0x3fffffff, }; diff --git a/lib/trace.c b/lib/trace.c index b9dc6d2e4b5..2e2c1bed54f 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -118,18 +118,6 @@ static void notrace add_ftrace(void *func_ptr, void *caller, ulong flags) hdr->ftrace_count++; } -static void notrace add_textbase(void) -{ - if (hdr->ftrace_count < hdr->ftrace_size) { - struct trace_call *rec = &hdr->ftrace[hdr->ftrace_count]; - - rec->func = CONFIG_TEXT_BASE; - rec->caller = 0; - rec->flags = FUNCF_TEXTBASE; - } - hdr->ftrace_count++; -} - /** * __cyg_profile_func_enter() - record function entry * @@ -278,8 +266,11 @@ int trace_list_calls(void *buff, size_t buff_size, size_t *needed) /* Update the header */ if (output_hdr) { + memset(output_hdr, '\0', sizeof(*output_hdr)); output_hdr->rec_count = upto; output_hdr->type = TRACE_CHUNK_CALLS; + output_hdr->version = TRACE_VERSION; + output_hdr->text_base = CONFIG_TEXT_BASE; } /* Work out how must of the buffer we used */ @@ -385,10 +376,9 @@ int notrace trace_init(void *buff, size_t buff_size) /* Use any remaining space for the timed function trace */ hdr->ftrace = (struct trace_call *)(buff + needed); hdr->ftrace_size = (buff_size - needed) / sizeof(*hdr->ftrace); - add_textbase(); + hdr->depth_limit = CONFIG_TRACE_CALL_DEPTH_LIMIT; puts("trace: enabled\n"); - hdr->depth_limit = CONFIG_TRACE_CALL_DEPTH_LIMIT; trace_enabled = 1; trace_inited = 1; @@ -426,7 +416,6 @@ int notrace trace_early_init(void) /* Use any remaining space for the timed function trace */ hdr->ftrace = (struct trace_call *)((char *)hdr + needed); hdr->ftrace_size = (buff_size - needed) / sizeof(*hdr->ftrace); - add_textbase(); hdr->depth_limit = CONFIG_TRACE_EARLY_CALL_DEPTH_LIMIT; printf("trace: early enable at %08x\n", CONFIG_TRACE_EARLY_ADDR); -- cgit v1.3.1 From c3d91812a2b69fbc73eccdcec70d7ea510d7c8bd Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:47 -0700 Subject: trace: Reduce the number of function sites Given that the compiler adds two function calls into each function, the current spacing is overkill. Drop it down to 16 bytes per function, which is still plenty. This saves some space in the trace buffer. Also move the calculation into a function, so it is common code. Add a check for gd->mon_len being unset, which breaks tracing. Signed-off-by: Simon Glass --- include/trace.h | 6 ++++-- lib/trace.c | 19 +++++++++++++++++-- 2 files changed, 21 insertions(+), 4 deletions(-) diff --git a/include/trace.h b/include/trace.h index 2be8d81b515..763d6d1255a 100644 --- a/include/trace.h +++ b/include/trace.h @@ -17,14 +17,16 @@ enum { * * The value here assumes a minimum instruction size of 4 bytes, * or that instructions are 2 bytes but there are at least 2 of - * them in every function. + * them in every function. Given that each function needs a call to + * __cyg_profile_func_enter() and __cyg_profile_func_exit() as well, + * we cannot have functions smaller that 16 bytes. * * Increasing this value reduces the number of functions we can * resolve, but reduces the size of the uintptr_t array used for * our function list, which is the length of the code divided by * this value. */ - FUNC_SITE_SIZE = 4, /* distance between function sites */ + FUNC_SITE_SIZE = 16, /* distance between function sites */ TRACE_VERSION = 1, }; diff --git a/lib/trace.c b/lib/trace.c index 2e2c1bed54f..12dae2089a4 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -321,6 +321,17 @@ void notrace trace_set_enabled(int enabled) trace_enabled = enabled != 0; } +static int get_func_count(void) +{ + /* Detect no support for mon_len since this means tracing cannot work */ + if (IS_ENABLED(CONFIG_SANDBOX) && !gd->mon_len) { + puts("Tracing is not supported on this board\n"); + return -ENOTSUPP; + } + + return gd->mon_len / FUNC_SITE_SIZE; +} + /** * trace_init() - initialize the tracing system and enable it * @@ -330,10 +341,12 @@ void notrace trace_set_enabled(int enabled) */ int notrace trace_init(void *buff, size_t buff_size) { - ulong func_count = gd->mon_len / FUNC_SITE_SIZE; + int func_count = get_func_count(); size_t needed; int was_disabled = !trace_enabled; + if (func_count < 0) + return func_count; trace_save_gd(); if (!was_disabled) { @@ -393,10 +406,12 @@ int notrace trace_init(void *buff, size_t buff_size) */ int notrace trace_early_init(void) { - ulong func_count = gd->mon_len / FUNC_SITE_SIZE; + int func_count = get_func_count(); size_t buff_size = CONFIG_TRACE_EARLY_SIZE; size_t needed; + if (func_count < 0) + return func_count; /* We can ignore additional calls to this function */ if (trace_enabled) return 0; -- cgit v1.3.1 From daca66d55f39551c3499de87397f08fbd3795a9b Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:48 -0700 Subject: trace: Track the minimum stack depth The trace does not necessarily start at the top level, so we can see it go negative. Track this so that we can show an accurate value for the stack depth. Signed-off-by: Simon Glass --- lib/trace.c | 24 ++++++++++++++++-------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/lib/trace.c b/lib/trace.c index 12dae2089a4..3551ef3a23c 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -35,9 +35,10 @@ struct trace_hdr { ulong ftrace_count; /* Num. of ftrace records written */ ulong ftrace_too_deep_count; /* Functions that were too deep */ - int depth; - int depth_limit; - int max_depth; + int depth; /* Depth of function calls */ + int depth_limit; /* Depth limit to trace to */ + int max_depth; /* Maximum depth seen so far */ + int min_depth; /* Minimum depth seen so far */ }; /* Pointer to start of trace buffer */ @@ -142,7 +143,7 @@ void notrace __cyg_profile_func_enter(void *func_ptr, void *caller) hdr->untracked_count++; } hdr->depth++; - if (hdr->depth > hdr->depth_limit) + if (hdr->depth > hdr->max_depth) hdr->max_depth = hdr->depth; trace_swap_gd(); } @@ -158,8 +159,10 @@ void notrace __cyg_profile_func_exit(void *func_ptr, void *caller) { if (trace_enabled) { trace_swap_gd(); - add_ftrace(func_ptr, caller, FUNCF_EXIT); hdr->depth--; + add_ftrace(func_ptr, caller, FUNCF_EXIT); + if (hdr->depth < hdr->min_depth) + hdr->min_depth = hdr->depth; trace_swap_gd(); } } @@ -309,8 +312,10 @@ void trace_print_stats(void) printf(" (%lu dropped due to overflow)", hdr->ftrace_count - hdr->ftrace_size); } - puts("\n"); - printf("%15d maximum observed call depth\n", hdr->max_depth); + + /* Add in minimum depth since the trace did not start at top level */ + printf("\n%15d maximum observed call depth\n", + hdr->max_depth - hdr->min_depth); printf("%15d call depth limit\n", hdr->depth_limit); print_grouped_ull(hdr->ftrace_too_deep_count, 10); puts(" calls not traced due to depth\n"); @@ -381,8 +386,10 @@ int notrace trace_init(void *buff, size_t buff_size) return -ENOSPC; } - if (was_disabled) + if (was_disabled) { memset(hdr, '\0', needed); + hdr->min_depth = INT_MAX; + } hdr->func_count = func_count; hdr->call_accum = (uintptr_t *)(hdr + 1); @@ -427,6 +434,7 @@ int notrace trace_early_init(void) memset(hdr, '\0', needed); hdr->call_accum = (uintptr_t *)(hdr + 1); hdr->func_count = func_count; + hdr->min_depth = INT_MAX; /* Use any remaining space for the timed function trace */ hdr->ftrace = (struct trace_call *)((char *)hdr + needed); -- cgit v1.3.1 From 9dd665ad333039a1b4f6c39cec088d7bf7eb787d Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:49 -0700 Subject: trace: Show a few more stats about tracing Add a few more useful items into the output. Update the buffers to use hex consistently. Signed-off-by: Simon Glass --- lib/trace.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/trace.c b/lib/trace.c index 3551ef3a23c..c3354a256fb 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -319,6 +319,10 @@ void trace_print_stats(void) printf("%15d call depth limit\n", hdr->depth_limit); print_grouped_ull(hdr->ftrace_too_deep_count, 10); puts(" calls not traced due to depth\n"); + print_grouped_ull(hdr->ftrace_size, 10); + puts(" max function calls\n"); + printf("\ntrace buffer %lx call records %lx\n", + (ulong)map_to_sysmem(hdr), (ulong)map_to_sysmem(hdr->ftrace)); } void notrace trace_set_enabled(int enabled) @@ -381,7 +385,7 @@ int notrace trace_init(void *buff, size_t buff_size) hdr = (struct trace_hdr *)buff; needed = sizeof(*hdr) + func_count * sizeof(uintptr_t); if (needed > buff_size) { - printf("trace: buffer size %zd bytes: at least %zd needed\n", + printf("trace: buffer size %zx bytes: at least %zx needed\n", buff_size, needed); return -ENOSPC; } @@ -426,7 +430,7 @@ int notrace trace_early_init(void) hdr = map_sysmem(CONFIG_TRACE_EARLY_ADDR, CONFIG_TRACE_EARLY_SIZE); needed = sizeof(*hdr) + func_count * sizeof(uintptr_t); if (needed > buff_size) { - printf("trace: buffer size is %zd bytes, at least %zd needed\n", + printf("trace: buffer size is %zx bytes, at least %zx needed\n", buff_size, needed); return -ENOSPC; } -- cgit v1.3.1 From 80f91558a173fe841810ab6a7a0f70b52344ec76 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:50 -0700 Subject: trace: Correct the relocation handover with buffer overflow When the early trace buffer overflows it leaves a gap in the trace buffer between where the actual data finished and where it would have finished if there were enough buffer space. This results in corrupted output. Adjust the logic to resolve this and add a message when the buffer overflows. Signed-off-by: Simon Glass --- lib/trace.c | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/lib/trace.c b/lib/trace.c index c3354a256fb..bbc316af295 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -360,8 +360,8 @@ int notrace trace_init(void *buff, size_t buff_size) if (!was_disabled) { #ifdef CONFIG_TRACE_EARLY + ulong used, count; char *end; - ulong used; /* * Copy over the early trace data if we have it. Disable @@ -370,12 +370,19 @@ int notrace trace_init(void *buff, size_t buff_size) trace_enabled = 0; hdr = map_sysmem(CONFIG_TRACE_EARLY_ADDR, CONFIG_TRACE_EARLY_SIZE); - end = (char *)&hdr->ftrace[min(hdr->ftrace_count, - hdr->ftrace_size)]; + count = min(hdr->ftrace_count, hdr->ftrace_size); + end = (char *)&hdr->ftrace[count]; used = end - (char *)hdr; printf("trace: copying %08lx bytes of early data from %x to %08lx\n", used, CONFIG_TRACE_EARLY_ADDR, (ulong)map_to_sysmem(buff)); + printf("%lu traced function calls", count); + if (hdr->ftrace_count > hdr->ftrace_size) { + printf(" (%lu dropped due to overflow)", + hdr->ftrace_count - hdr->ftrace_size); + hdr->ftrace_count = hdr->ftrace_size; + } + puts("\n"); memcpy(buff, hdr, used); #else puts("trace: already enabled\n"); -- cgit v1.3.1 From 852d4dbd70baa550cc5e8ef789aa719d30e94242 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:51 -0700 Subject: trace: Detect an infinite loop If something is wrong with a board's timer function such that it calls functions not marked with notrace, U-Boot will hang. Detect this, print a message and disable the trace. Signed-off-by: Simon Glass --- lib/trace.c | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/lib/trace.c b/lib/trace.c index bbc316af295..1091a5793a1 100644 --- a/lib/trace.c +++ b/lib/trace.c @@ -39,6 +39,7 @@ struct trace_hdr { int depth_limit; /* Depth limit to trace to */ int max_depth; /* Maximum depth seen so far */ int min_depth; /* Minimum depth seen so far */ + bool trace_locked; /* Used to detect recursive tracing */ }; /* Pointer to start of trace buffer */ @@ -133,6 +134,14 @@ void notrace __cyg_profile_func_enter(void *func_ptr, void *caller) if (trace_enabled) { int func; + if (hdr->trace_locked) { + trace_enabled = 0; + puts("trace: recursion detected, disabling\n"); + hdr->trace_locked = false; + return; + } + + hdr->trace_locked = true; trace_swap_gd(); add_ftrace(func_ptr, caller, FUNCF_ENTRY); func = func_ptr_to_num(func_ptr); @@ -146,6 +155,7 @@ void notrace __cyg_profile_func_enter(void *func_ptr, void *caller) if (hdr->depth > hdr->max_depth) hdr->max_depth = hdr->depth; trace_swap_gd(); + hdr->trace_locked = false; } } -- cgit v1.3.1 From 9efc0b279baabc7dc203937204953d641f0aa36e Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:52 -0700 Subject: trace: Rename prof to trace and improve comments The current use of 'profile' in some places is confusing. Update the code to use the word 'trace' consistently. Change the flags to better match their meaning and add some more comments. Signed-off-by: Simon Glass --- tools/proftool.c | 196 ++++++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 157 insertions(+), 39 deletions(-) diff --git a/tools/proftool.c b/tools/proftool.c index b66ea556486..6aa157c8b59 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -26,38 +26,62 @@ enum { FUNCF_TRACE = 1 << 0, /* Include this function in trace */ }; +/** + * struct func_info - information recorded for each function + * + * @offset: Function offset in the image, measured from the text_base + * @name: Function name + * @code_size: Total code size of the function + * @flags: Either 0 or FUNCF_TRACE + * @objsection: the section this function is in + */ struct func_info { unsigned long offset; const char *name; unsigned long code_size; - unsigned long call_count; unsigned flags; - /* the section this function is in */ struct objsection_info *objsection; }; +/** + * enum trace_line_type - whether to include or exclude a function + * + * @TRACE_LINE_INCLUDE: Include the function + * @TRACE_LINE_EXCLUDE: Exclude the function + */ enum trace_line_type { TRACE_LINE_INCLUDE, TRACE_LINE_EXCLUDE, }; +/** + * struct trace_configline_info - information about a config-file line + * + * @next: Next line + * @type: Line type + * @name: identifier name / wildcard + * @regex: Regex to use if name starts with '/' + */ struct trace_configline_info { struct trace_configline_info *next; enum trace_line_type type; - const char *name; /* identifier name / wildcard */ - regex_t regex; /* Regex to use if name starts with / */ + const char *name; + regex_t regex; }; /* The contents of the trace config file */ struct trace_configline_info *trace_config_head; +/* list of all functions in System.map file, sorted by offset in the image */ struct func_info *func_list; -int func_count; -struct trace_call *call_list; -int call_count; + +int func_count; /* number of functions */ +struct trace_call *call_list; /* list of all calls in the input trace file */ +int call_count; /* number of calls */ int verbose; /* Verbosity level 0=none, 1=warn, 2=notice, 3=info, 4=debug */ -unsigned long text_offset; /* text address of first function */ +ulong text_offset; /* text address of first function */ +/* debugging helpers */ static void outf(int level, const char *fmt, ...) __attribute__ ((format (__printf__, 2, 3))); #define error(fmt, b...) outf(0, fmt, ##b) @@ -66,7 +90,6 @@ static void outf(int level, const char *fmt, ...) #define info(fmt, b...) outf(3, fmt, ##b) #define debug(fmt, b...) outf(4, fmt, ##b) - static void outf(int level, const char *fmt, ...) { if (verbose >= level) { @@ -84,16 +107,24 @@ static void usage(void) "Usage: proftool [-cmtv] \n" "\n" "Commands\n" - " dump-ftrace\t\tDump out textual data in ftrace format\n" + " dump-ftrace\t\tDump out records in ftrace format for use by trace-cmd\n" "\n" "Options:\n" - " -c \tSpecific config file\n" + " -c \tSpecify config file\n" " -m \tSpecify Systen.map file\n" + " -o \tSpecify output file\n" " -t \tSpecify trace data file (from U-Boot 'trace calls')\n" " -v <0-4>\tSpecify verbosity\n"); exit(EXIT_FAILURE); } +/** + * h_cmp_offset - bsearch() function to compare two functions bny their offset + * + * @v1: Pointer to first function (struct func_info) + * @v2: Pointer to second function (struct func_info) + * Returns: < 0 if v1 offset < v2 offset, 0 if equal, > 0 otherwise + */ static int h_cmp_offset(const void *v1, const void *v2) { const struct func_info *f1 = v1, *f2 = v2; @@ -101,6 +132,15 @@ static int h_cmp_offset(const void *v1, const void *v2) return (f1->offset / FUNC_SITE_SIZE) - (f2->offset / FUNC_SITE_SIZE); } +/** + * read_system_map() - read the System.map file to create a list of functions + * + * This also reads the text_offset value, since we assume that the first text + * symbol is at that address + * + * @fin: File to read + * Returns: 0 if OK, non-zero on error + */ static int read_system_map(FILE *fin) { unsigned long offset, start = 0; @@ -152,6 +192,7 @@ static int read_system_map(FILE *fin) } notice("%d functions found in map file\n", func_count); text_offset = start; + return 0; } @@ -163,13 +204,22 @@ static int read_data(FILE *fin, void *buff, int size) if (!err) return 1; if (err != size) { - error("Cannot read profile file at pos %lx\n", ftell(fin)); + error("Cannot read trace file at pos %lx\n", ftell(fin)); return -1; } return 0; } -static struct func_info *find_func_by_offset(uint32_t offset) +/** + * find_func_by_offset() - Look up a function by its offset + * + * @offset: Offset to search for, from text_base + * Returns: function, if found, else NULL + * + * This does a fast search for a function given its offset from text_base + * + */ +static struct func_info *find_func_by_offset(uint offset) { struct func_info key, *found; @@ -180,8 +230,17 @@ static struct func_info *find_func_by_offset(uint32_t offset) return found; } -/* This finds the function which contains the given offset */ -static struct func_info *find_caller_by_offset(uint32_t offset) +/** + * find_caller_by_offset() - finds the function which contains the given offset + * + * @offset: Offset to search for, from text_base + * Returns: function, if found, else NULL + * + * If the offset falls between two functions, then it is assumed to belong to + * the first function (with the lowest offset). This is a way of figuring out + * which function owns code at a particular offset + */ +static struct func_info *find_caller_by_offset(uint offset) { int low; /* least function that could be a match */ int high; /* greated function that could be a match */ @@ -206,6 +265,15 @@ static struct func_info *find_caller_by_offset(uint32_t offset) return low >= 0 ? &func_list[low] : NULL; } +/** + * read_calls() - Read the list of calls from the trace data + * + * The calls are stored consecutively in the trace output produced by U-Boot + * + * @fin: File to read from + * @count: Number of calls to read + * Returns: 0 if OK, -1 on error + */ static int read_calls(FILE *fin, size_t count) { struct trace_call *call_data; @@ -222,16 +290,24 @@ static int read_calls(FILE *fin, size_t count) call_data = call_list; for (i = 0; i < count; i++, call_data++) { if (read_data(fin, call_data, sizeof(*call_data))) - return 1; + return -1; } return 0; } -static int read_profile(FILE *fin, int *not_found) +/** + * read_trace() - Read the U-Boot trace file + * + * Read in the calls from the trace file. The function list is ignored at + * present + * + * @fin: File to read + * Returns 0 if OK, non-zero on error + */ +static int read_trace(FILE *fin) { struct trace_output_hdr hdr; - *not_found = 0; while (!feof(fin)) { int err; @@ -255,6 +331,14 @@ static int read_profile(FILE *fin, int *not_found) return 0; } +/** + * read_map_file() - Read the System.map file + * + * This reads the file into the func_list array + * + * @fname: Filename to read + * Returns 0 if OK, non-zero on error + */ static int read_map_file(const char *fname) { FILE *fmap; @@ -272,28 +356,30 @@ static int read_map_file(const char *fname) return err; } -static int read_profile_file(const char *fname) +/** + * read_trace_file() - Open and read the U-Boot trace file + * + * Read in the calls from the trace file. The function list is ignored at + * present + * + * @fin: File to read + * Returns 0 if OK, non-zero on error + */ +static int read_trace_file(const char *fname) { - int not_found = INT_MAX; FILE *fprof; int err; fprof = fopen(fname, "rb"); if (!fprof) { - error("Cannot open profile data file '%s'\n", + error("Cannot open trace data file '%s'\n", fname); return 1; } else { - err = read_profile(fprof, ¬_found); + err = read_trace(fprof); fclose(fprof); if (err) return err; - - if (not_found) { - warn("%d profile functions could not be found in the map file - are you sure that your profile data and map file correspond?\n", - not_found); - return 1; - } } return 0; } @@ -344,6 +430,7 @@ static void check_trace_config_line(struct trace_configline_info *item) } } +/** check_trace_config() - Check trace-config file, reporting any problems */ static void check_trace_config(void) { struct trace_configline_info *line; @@ -377,6 +464,21 @@ static void check_functions(void) not_found, removed_code_size); } +/** + * read_trace_config() - read the trace-config file + * + * This file consists of lines like: + * + * include-func + * exclude-func + * + * where is a regular expression matched against function names. It + * allows some functions to be dropped from the trace when producing ftrace + * records + * + * @fin: File to process + * Returns: 0 if OK, -1 on error + */ static int read_trace_config(FILE *fin) { char buff[200]; @@ -400,8 +502,7 @@ static int read_trace_config(FILE *fin) if (!*s || *s == '#') continue; - line = (struct trace_configline_info *)calloc(1, - sizeof(*line)); + line = (struct trace_configline_info *)calloc(1, sizeof(*line)); if (!line) { error("Cannot allocate config line\n"); return -1; @@ -540,15 +641,25 @@ static int make_ftrace(void) return 0; } +/** + * prof_tool() - Performs requested action + * + * @argc: Number of arguments (used to obtain the command + * @argv: List of arguments + * @trace_fname: Filename of input file (trace data from U-Boot) + * @map_fname: Filename of map file (System.map from U-Boot) + * @trace_config_fname: Trace-configuration file, or NULL if none + * @out_fname: Output filename + */ static int prof_tool(int argc, char *const argv[], - const char *prof_fname, const char *map_fname, - const char *trace_config_fname) + const char *trace_fname, const char *map_fname, + const char *trace_config_fname, const char *out_fname) { int err = 0; if (read_map_file(map_fname)) return -1; - if (prof_fname && read_profile_file(prof_fname)) + if (trace_fname && read_trace_file(trace_fname)) return -1; if (trace_config_fname && read_trace_config_file(trace_config_fname)) return -1; @@ -572,27 +683,27 @@ int main(int argc, char *argv[]) const char *map_fname = "System.map"; const char *trace_fname = NULL; const char *config_fname = NULL; + const char *out_fname = NULL; int opt; verbose = 2; - while ((opt = getopt(argc, argv, "c:m:t:v:")) != -1) { + while ((opt = getopt(argc, argv, "c:m:o:t:v:")) != -1) { switch (opt) { case 'c': config_fname = optarg; break; - case 'm': map_fname = optarg; break; - + case 'o': + out_fname = optarg; + break; case 't': trace_fname = optarg; break; - case 'v': verbose = atoi(optarg); break; - default: usage(); } @@ -601,6 +712,13 @@ int main(int argc, char *argv[]) if (argc < 1) usage(); + if (!out_fname || !map_fname || !trace_fname) { + fprintf(stderr, + "Must provide trace data, System.map file and output file\n"); + usage(); + } + debug("Debug enabled\n"); - return prof_tool(argc, argv, trace_fname, map_fname, config_fname); + return prof_tool(argc, argv, trace_fname, map_fname, config_fname, + out_fname); } -- cgit v1.3.1 From be16fc81b2ed139363190a093d95ec5765696ccd Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:53 -0700 Subject: trace: Update proftool to use new binary format The old text format is not much used anymore. Instead a new trace-cmd tool has introduced a binary format for trace records. Add support for generating this format. This involves removing the old text format, adding various helpers for the new format and adjusting the code to use an output file instead of stdout. Signed-off-by: Simon Glass --- tools/Makefile | 3 + tools/proftool.c | 896 ++++++++++++++++++++++++++++++++++++++++++++++++++++--- 2 files changed, 854 insertions(+), 45 deletions(-) diff --git a/tools/Makefile b/tools/Makefile index 041c437e65b..e13effbb66a 100644 --- a/tools/Makefile +++ b/tools/Makefile @@ -215,7 +215,10 @@ hostprogs-$(CONFIG_NETCONSOLE) += ncb hostprogs-$(CONFIG_ARCH_KIRKWOOD) += kwboot hostprogs-$(CONFIG_ARCH_MVEBU) += kwboot + hostprogs-y += proftool +proftool-objs = proftool.o lib/abuf.o + hostprogs-$(CONFIG_STATIC_RELA) += relocate-rela hostprogs-$(CONFIG_RISCV) += prelink-riscv diff --git a/tools/proftool.c b/tools/proftool.c index 6aa157c8b59..feeef55c1b9 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -1,9 +1,15 @@ // SPDX-License-Identifier: GPL-2.0+ /* - * Copyright (c) 2013 Google, Inc + * Copyright 2023 Google LLC + * Written by Simon Glass */ -/* Decode and dump U-Boot profiling information */ +/* + * Decode and dump U-Boot trace information into formats that can be used + * by trace-cmd or kernelshark + * + * See doc/develop/trace.rst for more information + */ #include #include @@ -19,11 +25,67 @@ #include #include +#include + +/* Set to 1 to emit version 7 file (currently this doesn't work) */ +#define VERSION7 0 -#define MAX_LINE_LEN 500 +/* enable some debug features */ +#define _DEBUG 0 + +/* from linux/kernel.h */ +#define __ALIGN_MASK(x, mask) (((x) + (mask)) & ~(mask)) +#define ALIGN(x, a) __ALIGN_MASK((x), (typeof(x))(a) - 1) enum { FUNCF_TRACE = 1 << 0, /* Include this function in trace */ + TRACE_PAGE_SIZE = 4096, /* Assumed page size for trace */ + TRACE_PID = 1, /* PID to use for U-Boot */ + LEN_STACK_SIZE = 4, /* number of nested length fix-ups */ + TRACE_PAGE_MASK = TRACE_PAGE_SIZE - 1, + MAX_STACK_DEPTH = 50, /* Max nested function calls */ + MAX_LINE_LEN = 500, /* Max characters per line */ +}; + +/* Section types for v7 format (trace-cmd format) */ +enum { + SECTION_OPTIONS, +}; + +/* Option types (trace-cmd format) */ +enum { + OPTION_DONE, + OPTION_DATE, + OPTION_CPUSTAT, + OPTION_BUFFER, + OPTION_TRACECLOCK, + OPTION_UNAME, + OPTION_HOOK, + OPTION_OFFSET, + OPTION_CPUCOUNT, + OPTION_VERSION, + OPTION_PROCMAPS, + OPTION_TRACEID, + OPTION_TIME_SHIFT, + OPTION_GUEST, + OPTION_TSC2NSEC, +}; + +/* types of trace records (trace-cmd format) */ +enum trace_type { + __TRACE_FIRST_TYPE = 0, + + TRACE_FN, + TRACE_CTX, + TRACE_WAKE, + TRACE_STACK, + TRACE_PRINT, + TRACE_BPRINT, + TRACE_MMIO_RW, + TRACE_MMIO_MAP, + TRACE_BRANCH, + TRACE_GRAPH_RET, + TRACE_GRAPH_ENT, }; /** @@ -69,6 +131,45 @@ struct trace_configline_info { regex_t regex; }; +/** + * struct tw_len - holds information about a length value that need fix-ups + * + * This is used to record a placeholder for a u32 or u64 length which is written + * to the output file but needs to be updated once the length is actually known + * + * This allows us to write tw->ptr - @len_base to position @ptr in the file + * + * @ptr: Position of the length value in the file + * @base: Base position for the calculation + * @size: Size of the length value, in bytes (4 or 8) + */ +struct tw_len { + int ptr; + int base; + int size; +}; + +/** + * struct twriter - Writer for trace records + * + * Maintains state used when writing the output file in trace-cmd format + * + * @ptr: Current file position + * @len_stack: Stack of length values that need fixing up + * @len: Number of items on @len_stack + * @str_buf: Buffer of strings (for v7 format) + * @str_ptr: Current write-position in the buffer for strings + * @fout: Output file + */ +struct twriter { + int ptr; + struct tw_len len_stack[LEN_STACK_SIZE]; + int len_count; + struct abuf str_buf; + int str_ptr; + FILE *fout; +}; + /* The contents of the trace config file */ struct trace_configline_info *trace_config_head; @@ -569,56 +670,577 @@ static int read_trace_config_file(const char *fname) return err; } -static void out_func(ulong func_offset, int is_caller, const char *suffix) +/** + * tputh() - Write a 16-bit little-endian value to a file + * + * @fout: File to write to + * @val: Value to write + * Returns: number of bytes written (2) + */ +static int tputh(FILE *fout, unsigned int val) { - struct func_info *func; + fputc(val, fout); + fputc(val >> 8, fout); + + return 2; +} - func = (is_caller ? find_caller_by_offset : find_func_by_offset) - (func_offset); +/** + * tputl() - Write a 32-bit little-endian value to a file + * + * @fout: File to write to + * @val: Value to write + * Returns: number of bytes written (4) + */ +static int tputl(FILE *fout, ulong val) +{ + fputc(val, fout); + fputc(val >> 8, fout); + fputc(val >> 16, fout); + fputc(val >> 24, fout); - if (func) - printf("%s%s", func->name, suffix); - else - printf("%lx%s", func_offset, suffix); + return 4; } -/* - * # tracer: function - * # - * # TASK-PID CPU# TIMESTAMP FUNCTION - * # | | | | | - * # bash-4251 [01] 10152.583854: path_put <-path_walk - * # bash-4251 [01] 10152.583855: dput <-path_put - * # bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput +/** + * tputh() - Write a 64-bit little-endian value to a file + * + * @fout: File to write to + * @val: Value to write + * Returns: number of bytes written (8) */ -static int make_ftrace(void) +static int tputq(FILE *fout, unsigned long long val) { - struct trace_call *call; + tputl(fout, val); + tputl(fout, val >> 32U); + + return 8; +} + +/** + * tputh() - Write a string to a file + * + * The string is written without its terminator + * + * @fout: File to write to + * @val: Value to write + * Returns: number of bytes written + */ +static int tputs(FILE *fout, const char *str) +{ + fputs(str, fout); + + return strlen(str); +} + +/** + * add_str() - add a name string to the string table + * + * This is used by the v7 format + * + * @tw: Writer context + * @name: String to write + * Returns: Updated value of string pointer, or -1 if out of memory + */ +static int add_str(struct twriter *tw, const char *name) +{ + int str_ptr; + int len; + + len = strlen(name) + 1; + str_ptr = tw->str_ptr; + tw->str_ptr += len; + + if (tw->str_ptr > abuf_size(&tw->str_buf)) { + int new_size; + + new_size = ALIGN(tw->str_ptr, 4096); + if (!abuf_realloc(&tw->str_buf, new_size)) + return -1; + } + + return str_ptr; +} + +/** + * push_len() - Push a new length request onto the stack + * + * @tw: Writer context + * @base: Base position of the length calculation + * @msg: Indicates the type of caller, for debugging + * @size: Size of the length value, either 4 bytes or 8 + * Returns number of bytes written to the file (=@size on success), -ve on error + * + * This marks a place where a length must be written, covering data that is + * about to be written. It writes a placeholder value. + * + * Once the data is written, calling pop_len() will update the placeholder with + * the correct length based on how many bytes have been written + */ +static int push_len(struct twriter *tw, int base, const char *msg, int size) +{ + struct tw_len *lp; + + if (tw->len_count >= LEN_STACK_SIZE) { + fprintf(stderr, "Length-stack overflow: %s\n", msg); + return -1; + } + if (size != 4 && size != 8) { + fprintf(stderr, "Length-stack invalid size %d: %s\n", size, + msg); + return -1; + } + + lp = &tw->len_stack[tw->len_count++]; + lp->base = base; + lp->ptr = tw->ptr; + lp->size = size; + + return size == 8 ? tputq(tw->fout, 0) : tputl(tw->fout, 0); +} + +/** + * pop_len() - Update a length value once the length is known + * + * Pops a value of the length stack and updates the file at that position with + * the number of bytes written between now and then. Once done, the file is + * seeked to the current (tw->ptr) position again, so writing can continue as + * normal. + * + * @tw: Writer context + * @msg: Indicates the type of caller, for debugging + * Returns 0 if OK, -1 on error + */ +static int pop_len(struct twriter *tw, const char *msg) +{ + struct tw_len *lp; + int len, ret; + + if (!tw->len_count) { + fprintf(stderr, "Length-stack underflow: %s\n", msg); + return -1; + } + + lp = &tw->len_stack[--tw->len_count]; + if (fseek(tw->fout, lp->ptr, SEEK_SET)) + return -1; + len = tw->ptr - lp->base; + ret = lp->size == 8 ? tputq(tw->fout, len) : tputl(tw->fout, len); + if (ret < 0) + return -1; + if (fseek(tw->fout, tw->ptr, SEEK_SET)) + return -1; + + return 0; +} + +/** + * start_header() - Start a v7 section + * + * Writes a header in v7 format + * + * @tw: Writer context + * @id: ID of header to write (SECTION_...) + * @flags: Flags value to write + * @name: Name of section + * Returns: number of bytes written + */ +static int start_header(struct twriter *tw, int id, uint flags, + const char *name) +{ + int str_id; + int lptr; + int base; + int ret; + + base = tw->ptr + 16; + lptr = 0; + lptr += tputh(tw->fout, id); + lptr += tputh(tw->fout, flags); + str_id = add_str(tw, name); + if (str_id < 0) + return -1; + lptr += tputl(tw->fout, str_id); + + /* placeholder for size */ + ret = push_len(tw, base, "v7 header", 8); + if (ret < 0) + return -1; + lptr += ret; + + return lptr; +} + +/** + * start_page() - Start a new page of output data + * + * The output is arranged in 4KB pages with a base timestamp at the start of + * each. This starts a new page, making sure it is aligned to 4KB in the output + * file. + * + * @tw: Writer context + * @timestamp: Base timestamp for the page + */ +static int start_page(struct twriter *tw, ulong timestamp) +{ + int start; + int ret; + + /* move to start of next page */ + start = ALIGN(tw->ptr, TRACE_PAGE_SIZE); + ret = fseek(tw->fout, start, SEEK_SET); + if (ret < 0) { + fprintf(stderr, "Cannot seek to page start\n"); + return -1; + } + tw->ptr = start; + + /* page header */ + tw->ptr += tputq(tw->fout, timestamp); + ret = push_len(tw, start + 16, "page", 8); + if (ret < 0) + return ret; + tw->ptr += ret; + + return 0; +} + +/** + * finish_page() - finish a page + * + * Sets the lengths correctly and moves to the start of the next page + * + * @tw: Writer context + * Returns: 0 on success, -1 on error + */ +static int finish_page(struct twriter *tw) +{ + int ret, end; + + ret = pop_len(tw, "page"); + if (ret < 0) + return ret; + end = ALIGN(tw->ptr, TRACE_PAGE_SIZE); + + /* + * Write a byte so that the data actually makes to the file, in the case + * that we never write any more pages + */ + if (tw->ptr != end) { + if (fseek(tw->fout, end - 1, SEEK_SET)) { + fprintf(stderr, "cannot seek to start of next page\n"); + return -1; + } + fputc(0, tw->fout); + tw->ptr = end; + } + + return 0; +} + +/** + * output_headers() - Output v6 headers to the file + * + * Writes out the various formats so that trace-cmd and kernelshark can make + * sense of the data + * + * This updates tw->ptr as it goes + * + * @tw: Writer context + * Returns: 0 on success, -ve on error + */ +static int output_headers(struct twriter *tw) +{ + FILE *fout = tw->fout; + char str[800]; + int len, ret; + + tw->ptr += fprintf(fout, "%c%c%ctracing6%c%c%c", 0x17, 0x08, 0x44, + 0 /* terminator */, 0 /* little endian */, + 4 /* 32-bit long values */); + + /* host-machine page size 4KB */ + tw->ptr += tputl(fout, 4 << 10); + + tw->ptr += fprintf(fout, "header_page%c", 0); + + snprintf(str, sizeof(str), + "\tfield: u64 timestamp;\toffset:0;\tsize:8;\tsigned:0;\n" + "\tfield: local_t commit;\toffset:8;\tsize:8;\tsigned:1;\n" + "\tfield: int overwrite;\toffset:8;\tsize:1;\tsigned:1;\n" + "\tfield: char data;\toffset:16;\tsize:4080;\tsigned:1;\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + if (VERSION7) { + /* no compression */ + tw->ptr += fprintf(fout, "none%cversion%c\n", 0, 0); + + ret = start_header(tw, SECTION_OPTIONS, 0, "options"); + if (ret < 0) { + fprintf(stderr, "Cannot start option header\n"); + return -1; + } + tw->ptr += ret; + tw->ptr += tputh(fout, OPTION_DONE); + tw->ptr += tputl(fout, 8); + tw->ptr += tputl(fout, 0); + ret = pop_len(tw, "t7 header"); + if (ret < 0) { + fprintf(stderr, "Cannot finish option header\n"); + return -1; + } + } + + tw->ptr += fprintf(fout, "header_event%c", 0); + snprintf(str, sizeof(str), + "# compressed entry header\n" + "\ttype_len : 5 bits\n" + "\ttime_delta : 27 bits\n" + "\tarray : 32 bits\n" + "\n" + "\tpadding : type == 29\n" + "\ttime_extend : type == 30\n" + "\ttime_stamp : type == 31\n" + "\tdata max type_len == 28\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + /* number of ftrace-event-format files */ + tw->ptr += tputl(fout, 3); + + snprintf(str, sizeof(str), + "name: function\n" + "ID: 1\n" + "format:\n" + "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n" + "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n" + "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n" + "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n" + "\n" + "\tfield:unsigned long ip;\toffset:8;\tsize:8;\tsigned:0;\n" + "\tfield:unsigned long parent_ip;\toffset:16;\tsize:8;\tsigned:0;\n" + "\n" + "print fmt: \" %%ps <-- %%ps\", (void *)REC->ip, (void *)REC->parent_ip\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + snprintf(str, sizeof(str), + "name: funcgraph_entry\n" + "ID: 11\n" + "format:\n" + "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n" + "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n" + "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n" + "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n" + "\n" + "\tfield:unsigned long func;\toffset:8;\tsize:8;\tsigned:0;\n" + "\tfield:int depth;\toffset:16;\tsize:4;\tsigned:1;\n" + "\n" + "print fmt: \"--> %%ps (%%d)\", (void *)REC->func, REC->depth\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + snprintf(str, sizeof(str), + "name: funcgraph_exit\n" + "ID: 10\n" + "format:\n" + "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n" + "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n" + "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n" + "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n" + "\n" + "\tfield:unsigned long func;\toffset:8;\tsize:8;\tsigned:0;\n" + "\tfield:int depth;\toffset:16;\tsize:4;\tsigned:1;\n" + "\tfield:unsigned int overrun;\toffset:20;\tsize:4;\tsigned:0;\n" + "\tfield:unsigned long long calltime;\toffset:24;\tsize:8;\tsigned:0;\n" + "\tfield:unsigned long long rettime;\toffset:32;\tsize:8;\tsigned:0;\n" + "\n" + "print fmt: \"<-- %%ps (%%d) (start: %%llx end: %%llx) over: %%d\", (void *)REC->func, REC->depth, REC->calltime, REC->rettime, REC->depth\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + return 0; +} + +/** + * write_symbols() - Write the symbols out + * + * Writes the symbol information in the following format to mimic the Linux + * /proc/kallsyms file: + * + *
T + * + * This updates tw->ptr as it goes + * + * @tw: Writer context + * Returns: 0 on success, -ve on error + */ +static int write_symbols(struct twriter *tw) +{ + char str[200]; + int ret, i; + + /* write symbols */ + ret = push_len(tw, tw->ptr + 4, "syms", 4); + if (ret < 0) + return -1; + tw->ptr += ret; + for (i = 0; i < func_count; i++) { + struct func_info *func = &func_list[i]; + + snprintf(str, sizeof(str), "%016lx T %s\n", + text_offset + func->offset, func->name); + tw->ptr += tputs(tw->fout, str); + } + ret = pop_len(tw, "syms"); + if (ret < 0) + return -1; + tw->ptr += ret; + + return 0; +} + +/** + * write_options() - Write the options out + * + * Writes various options which are needed or useful. We use OPTION_TSC2NSEC + * to indicates that values in the output need to be multiplied by 1000 since + * U-Boot's trace values are in microseconds. + * + * This updates tw->ptr as it goes + * + * @tw: Writer context + * Returns: 0 on success, -ve on error + */ +static int write_options(struct twriter *tw) +{ + FILE *fout = tw->fout; + char str[200]; + int len; + + /* trace_printk, 0 for now */ + tw->ptr += tputl(fout, 0); + + /* processes */ + snprintf(str, sizeof(str), "%d u-boot\n", TRACE_PID); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + /* number of CPUs */ + tw->ptr += tputl(fout, 1); + + tw->ptr += fprintf(fout, "options %c", 0); + + /* traceclock */ + tw->ptr += tputh(fout, OPTION_TRACECLOCK); + tw->ptr += tputl(fout, 0); + + /* uname */ + tw->ptr += tputh(fout, OPTION_UNAME); + snprintf(str, sizeof(str), "U-Boot"); + len = strlen(str); + tw->ptr += tputl(fout, len); + tw->ptr += tputs(fout, str); + + /* version */ + tw->ptr += tputh(fout, OPTION_VERSION); + snprintf(str, sizeof(str), "unknown"); + len = strlen(str); + tw->ptr += tputl(fout, len); + tw->ptr += tputs(fout, str); + + /* trace ID */ + tw->ptr += tputh(fout, OPTION_TRACEID); + tw->ptr += tputl(fout, 8); + tw->ptr += tputq(fout, 0x123456780abcdef0); + + /* time conversion */ + tw->ptr += tputh(fout, OPTION_TSC2NSEC); + tw->ptr += tputl(fout, 16); + tw->ptr += tputl(fout, 1000); /* multiplier */ + tw->ptr += tputl(fout, 0); /* shift */ + tw->ptr += tputq(fout, 0); /* offset */ + + /* cpustat - bogus data for now, but at least it mentions the CPU */ + tw->ptr += tputh(fout, OPTION_CPUSTAT); + snprintf(str, sizeof(str), + "CPU: 0\n" + "entries: 100\n" + "overrun: 43565\n" + "commit overrun: 0\n" + "bytes: 3360\n" + "oldest event ts: 963732.447752\n" + "now ts: 963832.146824\n" + "dropped events: 0\n" + "read events: 42379\n"); + len = strlen(str); + tw->ptr += tputl(fout, len); + tw->ptr += tputs(fout, str); + + tw->ptr += tputh(fout, OPTION_DONE); + + return 0; +} + +/** + * write_pages() - Write the pages of trace data + * + * This works through all the calls, writing out as many pages of data as are + * needed. + * + * @tw: Writer context + * @missing_countp: Returns number of missing functions (not found in function + * list) + * @skip_countp: Returns number of skipped functions (excluded from trace) + * + * Returns: 0 on success, -ve on error + */ +static int write_pages(struct twriter *tw, int *missing_countp, + int *skip_countp) +{ + int stack_ptr; /* next free position in stack */ + int upto, page_upto, i; int missing_count = 0, skip_count = 0; - int i; + struct trace_call *call; + ulong last_timestamp; + FILE *fout = tw->fout; + int last_delta = 0; + int err_count; + bool in_page; + + in_page = false; + last_timestamp = 0; + upto = 0; + page_upto = 0; + err_count = 0; + + /* maintain a stack of start times for calling functions */ + stack_ptr = 0; - printf("# tracer: function\n" - "#\n" - "# entries-in-buffer/entries-written: 140080/250280 #P:4\n" - "#\n" - "# _-----=> irqs-off\n" - "# / _----=> need-resched\n" - "# | / _---=> hardirq/softirq\n" - "# || / _--=> preempt-depth\n" - "# ||| / delay\n" - "# TASK-PID CPU# |||| TIMESTAMP FUNCTION\n" - "# | | | |||| | |\n"); for (i = 0, call = call_list; i < call_count; i++, call++) { - struct func_info *func = find_func_by_offset(call->func); - ulong time = call->flags & FUNCF_TIMESTAMP_MASK; + struct func_info *caller_func; + struct func_info *func; + ulong timestamp; + uint rec_words; + int delta; - if (TRACE_CALL_TYPE(call) != FUNCF_ENTRY && - TRACE_CALL_TYPE(call) != FUNCF_EXIT) - continue; + func = find_func_by_offset(call->func); if (!func) { warn("Cannot find function at %lx\n", text_offset + call->func); missing_count++; + if (missing_count > 20) { + /* perhaps trace does not match System.map */ + fprintf(stderr, "Too many missing functions\n"); + return -1; + } continue; } @@ -629,12 +1251,186 @@ static int make_ftrace(void) continue; } - printf("%16s-%-5d [000] .... %lu.%06lu: ", "uboot", 1, - time / 1000000, time % 1000000); + rec_words = 6; - out_func(call->func, 0, " <- "); - out_func(call->caller, 1, "\n"); + /* convert timestamp from us to ns */ + timestamp = call->flags & FUNCF_TIMESTAMP_MASK; + if (in_page) { + if (page_upto + rec_words * 4 > TRACE_PAGE_SIZE) { + if (finish_page(tw)) + return -1; + in_page = false; + } + } + if (!in_page) { + if (start_page(tw, timestamp)) + return -1; + in_page = true; + last_timestamp = timestamp; + last_delta = 0; + page_upto = tw->ptr & TRACE_PAGE_MASK; + if (_DEBUG) { + fprintf(stderr, + "new page, last_timestamp=%ld, upto=%d\n", + last_timestamp, upto); + } + } + + delta = timestamp - last_timestamp; + if (delta < 0) { + fprintf(stderr, "Time went backwards\n"); + err_count++; + } + + if (err_count > 20) { + fprintf(stderr, "Too many errors, giving up\n"); + return -1; + } + + if (delta > 0x07fffff) { + /* + * hard to imagine how this could happen since it means + * that no function calls were made for a long time + */ + fprintf(stderr, "cannot represent time delta %x\n", + delta); + return -1; + } + + if (_DEBUG) { + fprintf(stderr, "%d: delta=%d, stamp=%ld\n", + upto, delta, timestamp); + fprintf(stderr, + " last_delta %x to %x: last_timestamp=%lx, timestamp=%lx, call->flags=%x, upto=%d\n", + last_delta, delta, last_timestamp, timestamp, call->flags, upto); + } + + /* type_len is 6, meaning 4 * 6 = 24 bytes */ + tw->ptr += tputl(fout, rec_words | (uint)delta << 5); + tw->ptr += tputh(fout, TRACE_FN); + tw->ptr += tputh(fout, 0); /* flags */ + tw->ptr += tputl(fout, TRACE_PID); /* PID */ + /* function */ + tw->ptr += tputq(fout, text_offset + func->offset); + caller_func = find_caller_by_offset(call->caller); + /* caller */ + tw->ptr += tputq(fout, text_offset + caller_func->offset); + + last_delta = delta; + last_timestamp = timestamp; + page_upto += 4 + rec_words * 4; + upto++; + if (stack_ptr == MAX_STACK_DEPTH) + break; } + if (in_page && finish_page(tw)) + return -1; + *missing_countp = missing_count; + *skip_countp = skip_count; + + return 0; +} + +/** + * write_flyrecord() - Write the flyrecord information + * + * Writes the header and pages of data for the "flyrecord" section. It also + * writes out the counter-type info, selecting "[local]" + * + * @tw: Writer context + * @missing_countp: Returns number of missing functions (not found in function + * list) + * @skip_countp: Returns number of skipped functions (excluded from trace) + * + * Returns: 0 on success, -ve on error + */ +static int write_flyrecord(struct twriter *tw, int *missing_countp, + int *skip_countp) +{ + int start, ret, len; + FILE *fout = tw->fout; + char str[200]; + + tw->ptr += fprintf(fout, "flyrecord%c", 0); + + /* trace data */ + start = ALIGN(tw->ptr + 16, TRACE_PAGE_SIZE); + tw->ptr += tputq(fout, start); + + /* use a placeholder for the size */ + ret = push_len(tw, start, "flyrecord", 8); + if (ret < 0) + return -1; + tw->ptr += ret; + + snprintf(str, sizeof(str), + "[local] global counter uptime perf mono mono_raw boot x86-tsc\n"); + len = strlen(str); + tw->ptr += tputq(fout, len); + tw->ptr += tputs(fout, str); + + ret = write_pages(tw, missing_countp, skip_countp); + if (ret < 0) { + fprintf(stderr, "Cannot output pages\n"); + return -1; + } + + ret = pop_len(tw, "flyrecord"); + if (ret < 0) { + fprintf(stderr, "Cannot finish flyrecord header\n"); + return -1; + } + + return 0; +} + +/** + * make_ftrace() - Write out an ftrace file + * + * See here for format: + * + * https://github.com/rostedt/trace-cmd/blob/master/Documentation/trace-cmd/trace-cmd.dat.v7.5.txt + * + * @fout: Output file + * Returns: 0 on success, -ve on error + */ +static int make_ftrace(FILE *fout) +{ + int missing_count, skip_count; + struct twriter tws, *tw = &tws; + int ret; + + memset(tw, '\0', sizeof(*tw)); + abuf_init(&tw->str_buf); + tw->fout = fout; + + tw->ptr = 0; + ret = output_headers(tw); + if (ret < 0) { + fprintf(stderr, "Cannot output headers\n"); + return -1; + } + /* number of event systems files */ + tw->ptr += tputl(fout, 0); + + ret = write_symbols(tw); + if (ret < 0) { + fprintf(stderr, "Cannot write symbols\n"); + return -1; + } + + ret = write_options(tw); + if (ret < 0) { + fprintf(stderr, "Cannot write options\n"); + return -1; + } + + ret = write_flyrecord(tw, &missing_count, &skip_count); + if (ret < 0) { + fprintf(stderr, "Cannot write flyrecord\n"); + return -1; + } + info("ftrace: %d functions not found, %d excluded\n", missing_count, skip_count); @@ -669,10 +1465,20 @@ static int prof_tool(int argc, char *const argv[], for (; argc; argc--, argv++) { const char *cmd = *argv; - if (0 == strcmp(cmd, "dump-ftrace")) - err = make_ftrace(); - else + if (!strcmp(cmd, "dump-ftrace")) { + FILE *fout; + + fout = fopen(out_fname, "w"); + if (!fout) { + fprintf(stderr, "Cannot write file '%s'\n", + out_fname); + return -1; + } + err = make_ftrace(fout); + fclose(fout); + } else { warn("Unknown command '%s'\n", cmd); + } } return err; -- cgit v1.3.1 From b15a16adf514b47fef2a50111e9af6493bee2e6a Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:54 -0700 Subject: trace: Drop use of objsection This feature was only partly implemented and serves no current purpose. Drop it. Signed-off-by: Simon Glass --- tools/proftool.c | 29 +---------------------------- 1 file changed, 1 insertion(+), 28 deletions(-) diff --git a/tools/proftool.c b/tools/proftool.c index feeef55c1b9..0d74e1169a9 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -95,14 +95,12 @@ enum trace_type { * @name: Function name * @code_size: Total code size of the function * @flags: Either 0 or FUNCF_TRACE - * @objsection: the section this function is in */ struct func_info { unsigned long offset; const char *name; unsigned long code_size; unsigned flags; - struct objsection_info *objsection; }; /** @@ -540,31 +538,6 @@ static void check_trace_config(void) check_trace_config_line(line); } -/** - * Check the functions to see if they each have an objsection. If not, then - * the linker must have eliminated them. - */ -static void check_functions(void) -{ - struct func_info *func, *end; - unsigned long removed_code_size = 0; - int not_found = 0; - - /* Look for missing functions */ - for (func = func_list, end = func + func_count; func < end; func++) { - if (!func->objsection) { - removed_code_size += func->code_size; - not_found++; - } - } - - /* Figure out what functions we want to trace */ - check_trace_config(); - - warn("%d functions removed by linker, %ld code size\n", - not_found, removed_code_size); -} - /** * read_trace_config() - read the trace-config file * @@ -1460,7 +1433,7 @@ static int prof_tool(int argc, char *const argv[], if (trace_config_fname && read_trace_config_file(trace_config_fname)) return -1; - check_functions(); + check_trace_config(); for (; argc; argc--, argv++) { const char *cmd = *argv; -- cgit v1.3.1 From 88716b550365996277303fb55a06afdfee076184 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:55 -0700 Subject: trace: Use text_base from the trace header Use the information in the trace header instead of reading it from the trace records. Add debugging to check that System.map and the trace header agree on this value. Signed-off-by: Simon Glass --- tools/proftool.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/tools/proftool.c b/tools/proftool.c index 0d74e1169a9..b5b8a9f7938 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -179,6 +179,7 @@ struct trace_call *call_list; /* list of all calls in the input trace file */ int call_count; /* number of calls */ int verbose; /* Verbosity level 0=none, 1=warn, 2=notice, 3=info, 4=debug */ ulong text_offset; /* text address of first function */ +ulong text_base; /* CONFIG_TEXT_BASE from trace file */ /* debugging helpers */ static void outf(int level, const char *fmt, ...) @@ -289,7 +290,8 @@ static int read_system_map(FILE *fin) if (func_count > 1) func[-1].code_size = func->offset - func[-1].offset; } - notice("%d functions found in map file\n", func_count); + notice("%d functions found in map file, start addr %lx\n", func_count, + start); text_offset = start; return 0; @@ -415,6 +417,7 @@ static int read_trace(FILE *fin) break; /* EOF */ else if (err) return 1; + text_base = hdr.text_base; switch (hdr.type) { case TRACE_CHUNK_FUNCS: @@ -1342,6 +1345,8 @@ static int write_flyrecord(struct twriter *tw, int *missing_countp, tw->ptr += tputq(fout, len); tw->ptr += tputs(fout, str); + debug("trace text base %lx, map file %lx\n", text_base, text_offset); + ret = write_pages(tw, missing_countp, skip_countp); if (ret < 0) { fprintf(stderr, "Cannot output pages\n"); -- cgit v1.3.1 From b54d8cf0b5b86a49399c1855f26361d8796d0491 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:56 -0700 Subject: trace: Support output of funcgraph records Add support for writing ftrace records in the 'funcgraph' format, which shows function entry and exit points as well as the time taken by each function. Signed-off-by: Simon Glass --- tools/proftool.c | 182 +++++++++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 150 insertions(+), 32 deletions(-) diff --git a/tools/proftool.c b/tools/proftool.c index b5b8a9f7938..588ae48a0c8 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -47,6 +47,19 @@ enum { MAX_LINE_LEN = 500, /* Max characters per line */ }; +/** + * enum out_format_t - supported output formats + * + * @OUT_FMT_DEFAULT: Use the default for the output file + * @OUT_FMT_FUNCTION: Write ftrace 'function' records + * @OUT_FMT_FUNCGRAPH: Write ftrace funcgraph_entry and funcgraph_exit records + */ +enum out_format_t { + OUT_FMT_DEFAULT, + OUT_FMT_FUNCTION, + OUT_FMT_FUNCGRAPH, +}; + /* Section types for v7 format (trace-cmd format) */ enum { SECTION_OPTIONS, @@ -211,10 +224,15 @@ static void usage(void) "\n" "Options:\n" " -c \tSpecify config file\n" + " -f \tSpecify output subtype\n" " -m \tSpecify Systen.map file\n" " -o \tSpecify output file\n" " -t \tSpecify trace data file (from U-Boot 'trace calls')\n" - " -v <0-4>\tSpecify verbosity\n"); + " -v <0-4>\tSpecify verbosity\n" + "\n" + "Subtypes for dump-ftrace:\n" + " function - write function-call records (caller/callee)\n" + " funcgraph - write function entry/exit records (graph)\n"); exit(EXIT_FAILURE); } @@ -1165,6 +1183,43 @@ static int write_options(struct twriter *tw) return 0; } +/** + * calc_min_depth() - Calculate the minimum call depth from the call list + * + * Starting with a depth of 0, this works through the call list, adding 1 for + * each function call and subtracting 1 for each function return. Most likely + * the value ends up being negative, since the trace does not start at the + * very top of the call stack, e.g. main(), but some function called by that. + * + * This value can be used to calculate the depth value for the first call, + * such that it never goes negative for subsequent returns. + * + * Returns: minimum call depth (e.g. -2) + */ +static int calc_min_depth(void) +{ + struct trace_call *call; + int depth, min_depth, i; + + /* Calculate minimum depth */ + depth = 0; + min_depth = 0; + for (i = 0, call = call_list; i < call_count; i++, call++) { + switch (TRACE_CALL_TYPE(call)) { + case FUNCF_ENTRY: + depth++; + break; + case FUNCF_EXIT: + depth--; + if (depth < min_depth) + min_depth = depth; + break; + } + } + + return min_depth; +} + /** * write_pages() - Write the pages of trace data * @@ -1172,17 +1227,19 @@ static int write_options(struct twriter *tw) * needed. * * @tw: Writer context + * @out_format: Output format to use * @missing_countp: Returns number of missing functions (not found in function * list) * @skip_countp: Returns number of skipped functions (excluded from trace) * * Returns: 0 on success, -ve on error */ -static int write_pages(struct twriter *tw, int *missing_countp, - int *skip_countp) +static int write_pages(struct twriter *tw, enum out_format_t out_format, + int *missing_countp, int *skip_countp) { + ulong func_stack[MAX_STACK_DEPTH]; int stack_ptr; /* next free position in stack */ - int upto, page_upto, i; + int upto, depth, page_upto, i; int missing_count = 0, skip_count = 0; struct trace_call *call; ulong last_timestamp; @@ -1200,8 +1257,13 @@ static int write_pages(struct twriter *tw, int *missing_countp, /* maintain a stack of start times for calling functions */ stack_ptr = 0; + /* + * The first thing in the trace may not be the top-level function, so + * set the initial depth so that no function goes below depth 0 + */ + depth = -calc_min_depth(); for (i = 0, call = call_list; i < call_count; i++, call++) { - struct func_info *caller_func; + bool entry = TRACE_CALL_TYPE(call) == FUNCF_ENTRY; struct func_info *func; ulong timestamp; uint rec_words; @@ -1227,7 +1289,10 @@ static int write_pages(struct twriter *tw, int *missing_countp, continue; } - rec_words = 6; + if (out_format == OUT_FMT_FUNCTION) + rec_words = 6; + else /* 2 header words and then 3 or 8 others */ + rec_words = 2 + (entry ? 3 : 8); /* convert timestamp from us to ns */ timestamp = call->flags & FUNCF_TIMESTAMP_MASK; @@ -1273,24 +1338,59 @@ static int write_pages(struct twriter *tw, int *missing_countp, return -1; } - if (_DEBUG) { - fprintf(stderr, "%d: delta=%d, stamp=%ld\n", - upto, delta, timestamp); - fprintf(stderr, - " last_delta %x to %x: last_timestamp=%lx, timestamp=%lx, call->flags=%x, upto=%d\n", - last_delta, delta, last_timestamp, timestamp, call->flags, upto); - } + if (out_format == OUT_FMT_FUNCTION) { + struct func_info *caller_func; - /* type_len is 6, meaning 4 * 6 = 24 bytes */ - tw->ptr += tputl(fout, rec_words | (uint)delta << 5); - tw->ptr += tputh(fout, TRACE_FN); - tw->ptr += tputh(fout, 0); /* flags */ - tw->ptr += tputl(fout, TRACE_PID); /* PID */ - /* function */ - tw->ptr += tputq(fout, text_offset + func->offset); - caller_func = find_caller_by_offset(call->caller); - /* caller */ - tw->ptr += tputq(fout, text_offset + caller_func->offset); + if (_DEBUG) { + fprintf(stderr, "%d: delta=%d, stamp=%ld\n", + upto, delta, timestamp); + fprintf(stderr, + " last_delta %x to %x: last_timestamp=%lx, " + "timestamp=%lx, call->flags=%x, upto=%d\n", + last_delta, delta, last_timestamp, + timestamp, call->flags, upto); + } + + /* type_len is 6, meaning 4 * 6 = 24 bytes */ + tw->ptr += tputl(fout, rec_words | (uint)delta << 5); + tw->ptr += tputh(fout, TRACE_FN); + tw->ptr += tputh(fout, 0); /* flags */ + tw->ptr += tputl(fout, TRACE_PID); /* PID */ + /* function */ + tw->ptr += tputq(fout, text_offset + func->offset); + caller_func = find_caller_by_offset(call->caller); + /* caller */ + tw->ptr += tputq(fout, + text_offset + caller_func->offset); + } else { + tw->ptr += tputl(fout, rec_words | delta << 5); + tw->ptr += tputh(fout, entry ? TRACE_GRAPH_ENT + : TRACE_GRAPH_RET); + tw->ptr += tputh(fout, 0); /* flags */ + tw->ptr += tputl(fout, TRACE_PID); /* PID */ + /* function */ + tw->ptr += tputq(fout, text_offset + func->offset); + tw->ptr += tputl(fout, depth); /* depth */ + if (entry) { + depth++; + if (stack_ptr < MAX_STACK_DEPTH) + func_stack[stack_ptr] = timestamp; + stack_ptr++; + } else { + ulong func_duration = 0; + + depth--; + if (stack_ptr && stack_ptr <= MAX_STACK_DEPTH) { + ulong start = func_stack[--stack_ptr]; + + func_duration = timestamp - start; + } + tw->ptr += tputl(fout, 0); /* overrun */ + tw->ptr += tputq(fout, 0); /* calltime */ + /* rettime */ + tw->ptr += tputq(fout, func_duration); + } + } last_delta = delta; last_timestamp = timestamp; @@ -1314,14 +1414,15 @@ static int write_pages(struct twriter *tw, int *missing_countp, * writes out the counter-type info, selecting "[local]" * * @tw: Writer context + * @out_format: Output format to use * @missing_countp: Returns number of missing functions (not found in function * list) * @skip_countp: Returns number of skipped functions (excluded from trace) * * Returns: 0 on success, -ve on error */ -static int write_flyrecord(struct twriter *tw, int *missing_countp, - int *skip_countp) +static int write_flyrecord(struct twriter *tw, enum out_format_t out_format, + int *missing_countp, int *skip_countp) { int start, ret, len; FILE *fout = tw->fout; @@ -1347,7 +1448,7 @@ static int write_flyrecord(struct twriter *tw, int *missing_countp, debug("trace text base %lx, map file %lx\n", text_base, text_offset); - ret = write_pages(tw, missing_countp, skip_countp); + ret = write_pages(tw, out_format, missing_countp, skip_countp); if (ret < 0) { fprintf(stderr, "Cannot output pages\n"); return -1; @@ -1370,9 +1471,10 @@ static int write_flyrecord(struct twriter *tw, int *missing_countp, * https://github.com/rostedt/trace-cmd/blob/master/Documentation/trace-cmd/trace-cmd.dat.v7.5.txt * * @fout: Output file + * @out_format: Output format to use * Returns: 0 on success, -ve on error */ -static int make_ftrace(FILE *fout) +static int make_ftrace(FILE *fout, enum out_format_t out_format) { int missing_count, skip_count; struct twriter tws, *tw = &tws; @@ -1403,7 +1505,7 @@ static int make_ftrace(FILE *fout) return -1; } - ret = write_flyrecord(tw, &missing_count, &skip_count); + ret = write_flyrecord(tw, out_format, &missing_count, &skip_count); if (ret < 0) { fprintf(stderr, "Cannot write flyrecord\n"); return -1; @@ -1427,7 +1529,8 @@ static int make_ftrace(FILE *fout) */ static int prof_tool(int argc, char *const argv[], const char *trace_fname, const char *map_fname, - const char *trace_config_fname, const char *out_fname) + const char *trace_config_fname, const char *out_fname, + enum out_format_t out_format) { int err = 0; @@ -1446,13 +1549,16 @@ static int prof_tool(int argc, char *const argv[], if (!strcmp(cmd, "dump-ftrace")) { FILE *fout; + if (out_format != OUT_FMT_FUNCTION && + out_format != OUT_FMT_FUNCGRAPH) + out_format = OUT_FMT_FUNCTION; fout = fopen(out_fname, "w"); if (!fout) { fprintf(stderr, "Cannot write file '%s'\n", out_fname); return -1; } - err = make_ftrace(fout); + err = make_ftrace(fout, out_format); fclose(fout); } else { warn("Unknown command '%s'\n", cmd); @@ -1464,6 +1570,7 @@ static int prof_tool(int argc, char *const argv[], int main(int argc, char *argv[]) { + enum out_format_t out_format = OUT_FMT_DEFAULT; const char *map_fname = "System.map"; const char *trace_fname = NULL; const char *config_fname = NULL; @@ -1471,11 +1578,22 @@ int main(int argc, char *argv[]) int opt; verbose = 2; - while ((opt = getopt(argc, argv, "c:m:o:t:v:")) != -1) { + while ((opt = getopt(argc, argv, "c:f:m:o:t:v:")) != -1) { switch (opt) { case 'c': config_fname = optarg; break; + case 'f': + if (!strcmp("function", optarg)) { + out_format = OUT_FMT_FUNCTION; + } else if (!strcmp("funcgraph", optarg)) { + out_format = OUT_FMT_FUNCGRAPH; + } else { + fprintf(stderr, + "Invalid format: use function, funcgraph, calls, timing\n"); + exit(1); + } + break; case 'm': map_fname = optarg; break; @@ -1504,5 +1622,5 @@ int main(int argc, char *argv[]) debug("Debug enabled\n"); return prof_tool(argc, argv, trace_fname, map_fname, config_fname, - out_fname); + out_fname, out_format); } -- cgit v1.3.1 From 47b89d61f2a867f07455d5a3d89df0e7d7a6ec9a Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:57 -0700 Subject: trace: Support output of a flamegraph It is useful to see how many times each function is called, particularly in the context of its callers. A flamegraph is a way of showing this. Support output in this format which can be used by the flamegraph.pl script, to generate an SVG image for browsing. Signed-off-by: Simon Glass --- tools/proftool.c | 272 ++++++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 271 insertions(+), 1 deletion(-) diff --git a/tools/proftool.c b/tools/proftool.c index 588ae48a0c8..844ff3d0d06 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -6,7 +6,7 @@ /* * Decode and dump U-Boot trace information into formats that can be used - * by trace-cmd or kernelshark + * by trace-cmd, kernelshark or flamegraph.pl * * See doc/develop/trace.rst for more information */ @@ -27,6 +27,8 @@ #include #include +#include + /* Set to 1 to emit version 7 file (currently this doesn't work) */ #define VERSION7 0 @@ -37,6 +39,18 @@ #define __ALIGN_MASK(x, mask) (((x) + (mask)) & ~(mask)) #define ALIGN(x, a) __ALIGN_MASK((x), (typeof(x))(a) - 1) +/** + * container_of - cast a member of a structure out to the containing structure + * @ptr: the pointer to the member. + * @type: the type of the container struct this is embedded in. + * @member: the name of the member within the struct. + * + * (this is needed by list.h) + */ +#define container_of(ptr, type, member) ({ \ + const typeof( ((type *)0)->member ) *__mptr = (ptr); \ + (type *)( (char *)__mptr - offsetof(type,member) );}) + enum { FUNCF_TRACE = 1 << 0, /* Include this function in trace */ TRACE_PAGE_SIZE = 4096, /* Assumed page size for trace */ @@ -101,6 +115,38 @@ enum trace_type { TRACE_GRAPH_ENT, }; +/** + * struct flame_node - a node in the call-stack tree + * + * Each stack frame detected in the trace is given a node corresponding to a + * function call in the call stack. Functions can appear multiple times when + * they are called by a different set of parent functions. + * + * @parent: Parent node (the call stack for the function that called this one) + * @child_head: List of children of this node (functions called from here) + * @sibling: Next node in the list of children + * @func: Function this node refers to (NULL for root node) + * @count: Number of times this call-stack occurred + */ +struct flame_node { + struct flame_node *parent; + struct list_head child_head; + struct list_head sibling_node; + struct func_info *func; + int count; +}; + +/** + * struct flame_state - state information for building the flame graph + * + * @node: Current node being processed (corresponds to a function call) + * @nodes: Number of nodes created (running count) + */ +struct flame_state { + struct flame_node *node; + int nodes; +}; + /** * struct func_info - information recorded for each function * @@ -221,6 +267,7 @@ static void usage(void) "\n" "Commands\n" " dump-ftrace\t\tDump out records in ftrace format for use by trace-cmd\n" + " dump-flamegraph\tWrite a file for use with flamegraph.pl\n" "\n" "Options:\n" " -c \tSpecify config file\n" @@ -1517,6 +1564,218 @@ static int make_ftrace(FILE *fout, enum out_format_t out_format) return 0; } +/** + * create_node() - Create a new node in the flamegraph tree + * + * @msg: Message to use for debugging if something goes wrong + * Returns: Pointer to newly created node, or NULL on error + */ +static struct flame_node *create_node(const char *msg) +{ + struct flame_node *node; + + node = calloc(1, sizeof(*node)); + if (!node) { + fprintf(stderr, "Out of memory for %s\n", msg); + return NULL; + } + INIT_LIST_HEAD(&node->child_head); + + return node; +} + +/** + * process_call(): Add a call to the flamegraph info + * + * For function calls, if this call stack has been seen before, this increments + * the call count, creating a new node if needed. + * + * For function returns, it adds up the time spent in this call stack, + * subtracting the time spent by child functions. + * + * @state: Current flamegraph state + * @entry: true if this is a function entry, false if a function exit + * @timestamp: Timestamp from the trace file (in microseconds) + * @func: Function that was called/returned from + * + * Returns: 0 on success, -ve on error + */ +static int process_call(struct flame_state *state, bool entry, ulong timestamp, + struct func_info *func) +{ + struct flame_node *node = state->node; + + if (entry) { + struct flame_node *child, *chd; + + /* see if we have this as a child node already */ + child = NULL; + list_for_each_entry(chd, &node->child_head, sibling_node) { + if (chd->func == func) { + child = chd; + break; + } + } + if (!child) { + /* create a new node */ + child = create_node("child"); + if (!child) + return -1; + list_add_tail(&child->sibling_node, &node->child_head); + child->func = func; + child->parent = node; + state->nodes++; + } + debug("entry %s: move from %s to %s\n", func->name, + node->func ? node->func->name : "(root)", + child->func->name); + child->count++; + node = child; + } else if (node->parent) { + debug("exit %s: move from %s to %s\n", func->name, + node->func->name, node->parent->func ? + node->parent->func->name : "(root)"); + node = node->parent; + } + + state->node = node; + + return 0; +} + +/** + * make_flame_tree() - Create a tree of stack traces + * + * Set up a tree, with the root node having the top-level functions as children + * and the leaf nodes being leaf functions. Each node has a count of how many + * times this function appears in the trace + * + * @treep: Returns the resulting flamegraph tree + * Returns: 0 on success, -ve on error + */ +static int make_flame_tree(struct flame_node **treep) +{ + struct flame_state state; + struct flame_node *tree; + struct trace_call *call; + int missing_count = 0; + int i, depth; + + /* + * The first thing in the trace may not be the top-level function, so + * set the initial depth so that no function goes below depth 0 + */ + depth = -calc_min_depth(); + + tree = create_node("tree"); + if (!tree) + return -1; + state.node = tree; + state.nodes = 0; + + for (i = 0, call = call_list; i < call_count; i++, call++) { + bool entry = TRACE_CALL_TYPE(call) == FUNCF_ENTRY; + ulong timestamp = call->flags & FUNCF_TIMESTAMP_MASK; + struct func_info *func; + + if (entry) + depth++; + else + depth--; + + func = find_func_by_offset(call->func); + if (!func) { + warn("Cannot find function at %lx\n", + text_offset + call->func); + missing_count++; + continue; + } + + if (process_call(&state, entry, timestamp, func)) + return -1; + } + fprintf(stderr, "%d nodes\n", state.nodes); + *treep = tree; + + return 0; +} + +/** + * output_tree() - Output a flamegraph tree + * + * Writes the tree out to a file in a format suitable for flamegraph.pl + * + * This works by maintaining a string shared across all recursive calls. The + * function name for this node is added to the existing string, to make up the + * full call-stack description. For example, on entry, @str might contain: + * + * "initf_bootstage;bootstage_mark_name" + * ^ @base + * + * with @base pointing to the \0 at the end of the string. This function adds + * a ';' following by the name of the current function, e.g. "timer_get_boot_us" + * as well as the output value, to get the full line: + * + * initf_bootstage;bootstage_mark_name;timer_get_boot_us 123 + * + * @fout: Output file + * @node: Node to output (pass the whole tree at first) + * @str: String to use to build the output line (e.g. 500 charas long) + * @maxlen: Maximum length of string + * @base: Current base position in the string + * @treep: Returns the resulting flamegraph tree + * Returns 0 if OK, -1 on error + */ +static int output_tree(FILE *fout, const struct flame_node *node, + char *str, int maxlen, int base) +{ + const struct flame_node *child; + int pos; + + if (node->count) + fprintf(fout, "%s %d\n", str, node->count); + + pos = base; + if (pos) + str[pos++] = ';'; + list_for_each_entry(child, &node->child_head, sibling_node) { + int len; + + len = strlen(child->func->name); + if (pos + len + 1 >= maxlen) { + fprintf(stderr, "String too short (%d chars)\n", + maxlen); + return -1; + } + strcpy(str + pos, child->func->name); + if (output_tree(fout, child, str, maxlen, pos + len)) + return -1; + } + + return 0; +} + +/** + * make_flamegraph() - Write out a flame graph + * + * @fout: Output file + * Returns 0 if OK, -1 on error + */ +static int make_flamegraph(FILE *fout) +{ + struct flame_node *tree; + char str[500]; + + if (make_flame_tree(&tree)) + return -1; + + *str = '\0'; + if (output_tree(fout, tree, str, sizeof(str), 0)) + return -1; + + return 0; +} + /** * prof_tool() - Performs requested action * @@ -1560,6 +1819,17 @@ static int prof_tool(int argc, char *const argv[], } err = make_ftrace(fout, out_format); fclose(fout); + } else if (!strcmp(cmd, "dump-flamegraph")) { + FILE *fout; + + fout = fopen(out_fname, "w"); + if (!fout) { + fprintf(stderr, "Cannot write file '%s'\n", + out_fname); + return -1; + } + err = make_flamegraph(fout); + fclose(fout); } else { warn("Unknown command '%s'\n", cmd); } -- cgit v1.3.1 From 97f3024d16915fd885336c8b983c8a47ac19bcd8 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:58 -0700 Subject: trace: Provide a flamegraph that uses timing Add a second variant of the flame graph that shows records in terms of the number of microseconds used by each call stack. This is a useful way of seeing where time is going within the execution of U-Boot. This requires a call stack that records the start time of each function, as well as a way of subtracting all time consumed by child functions, so that this time is not counted twice by the flamegraph. The time values in the output are just for the function itself, not for its children. Signed-off-by: Simon Glass --- tools/proftool.c | 108 +++++++++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 97 insertions(+), 11 deletions(-) diff --git a/tools/proftool.c b/tools/proftool.c index 844ff3d0d06..089360428c2 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -67,11 +67,16 @@ enum { * @OUT_FMT_DEFAULT: Use the default for the output file * @OUT_FMT_FUNCTION: Write ftrace 'function' records * @OUT_FMT_FUNCGRAPH: Write ftrace funcgraph_entry and funcgraph_exit records + * @OUT_FMT_FLAMEGRAPH_CALLS: Write a file suitable for flamegraph.pl + * @OUT_FMT_FLAMEGRAPH_TIMING: Write a file suitable for flamegraph.pl with the + * counts set to the number of microseconds used by each function */ enum out_format_t { OUT_FMT_DEFAULT, OUT_FMT_FUNCTION, OUT_FMT_FUNCGRAPH, + OUT_FMT_FLAMEGRAPH_CALLS, + OUT_FMT_FLAMEGRAPH_TIMING, }; /* Section types for v7 format (trace-cmd format) */ @@ -127,6 +132,8 @@ enum trace_type { * @sibling: Next node in the list of children * @func: Function this node refers to (NULL for root node) * @count: Number of times this call-stack occurred + * @duration: Number of microseconds taken to run this function, excluding all + * of the functions it calls */ struct flame_node { struct flame_node *parent; @@ -134,16 +141,27 @@ struct flame_node { struct list_head sibling_node; struct func_info *func; int count; + ulong duration; }; /** * struct flame_state - state information for building the flame graph * * @node: Current node being processed (corresponds to a function call) + * @stack: Stack of call-start time for this function as well as the + * accumulated total time of all child calls (so we can subtract them from the + * function's call time. This is an 'empty' stack, meaning that @stack_ptr + * points to the next available stack position + * @stack_ptr: points to first empty position in the stack * @nodes: Number of nodes created (running count) */ struct flame_state { struct flame_node *node; + struct stack_info { + ulong timestamp; + ulong child_total; + } stack[MAX_STACK_DEPTH]; + int stack_ptr; int nodes; }; @@ -279,7 +297,11 @@ static void usage(void) "\n" "Subtypes for dump-ftrace:\n" " function - write function-call records (caller/callee)\n" - " funcgraph - write function entry/exit records (graph)\n"); + " funcgraph - write function entry/exit records (graph)\n" + "\n" + "Subtypes for dump-flamegraph\n" + " calls - create a flamegraph of stack frames\n" + " timing - create a flamegraph of microseconds for each stack frame\n"); exit(EXIT_FAILURE); } @@ -1604,6 +1626,7 @@ static int process_call(struct flame_state *state, bool entry, ulong timestamp, struct func_info *func) { struct flame_node *node = state->node; + int stack_ptr = state->stack_ptr; if (entry) { struct flame_node *child, *chd; @@ -1630,14 +1653,44 @@ static int process_call(struct flame_state *state, bool entry, ulong timestamp, node->func ? node->func->name : "(root)", child->func->name); child->count++; + if (stack_ptr < MAX_STACK_DEPTH) { + state->stack[stack_ptr].timestamp = timestamp; + state->stack[stack_ptr].child_total = 0; + } + debug("%d: %20s: entry at %ld\n", stack_ptr, func->name, + timestamp); + stack_ptr++; node = child; } else if (node->parent) { + ulong total_duration = 0, child_duration = 0; + struct stack_info *stk; + debug("exit %s: move from %s to %s\n", func->name, node->func->name, node->parent->func ? node->parent->func->name : "(root)"); + if (stack_ptr && stack_ptr <= MAX_STACK_DEPTH) { + stk = &state->stack[--stack_ptr]; + + /* + * get total duration of the function which just + * exited + */ + total_duration = timestamp - stk->timestamp; + child_duration = stk->child_total; + + if (stack_ptr) + state->stack[stack_ptr - 1].child_total += total_duration; + + debug("%d: %20s: exit at %ld, total %ld, child %ld, child_total=%ld\n", + stack_ptr, func->name, timestamp, + total_duration, child_duration, + stk->child_total); + } + node->duration += total_duration - child_duration; node = node->parent; } + state->stack_ptr = stack_ptr; state->node = node; return 0; @@ -1650,10 +1703,12 @@ static int process_call(struct flame_state *state, bool entry, ulong timestamp, * and the leaf nodes being leaf functions. Each node has a count of how many * times this function appears in the trace * + * @out_format: Output format to use * @treep: Returns the resulting flamegraph tree * Returns: 0 on success, -ve on error */ -static int make_flame_tree(struct flame_node **treep) +static int make_flame_tree(enum out_format_t out_format, + struct flame_node **treep) { struct flame_state state; struct flame_node *tree; @@ -1661,6 +1716,9 @@ static int make_flame_tree(struct flame_node **treep) int missing_count = 0; int i, depth; + /* maintain a stack of start times, etc. for 'calling' functions */ + state.stack_ptr = 0; + /* * The first thing in the trace may not be the top-level function, so * set the initial depth so that no function goes below depth 0 @@ -1719,6 +1777,7 @@ static int make_flame_tree(struct flame_node **treep) * initf_bootstage;bootstage_mark_name;timer_get_boot_us 123 * * @fout: Output file + * @out_format: Output format to use * @node: Node to output (pass the whole tree at first) * @str: String to use to build the output line (e.g. 500 charas long) * @maxlen: Maximum length of string @@ -1726,14 +1785,32 @@ static int make_flame_tree(struct flame_node **treep) * @treep: Returns the resulting flamegraph tree * Returns 0 if OK, -1 on error */ -static int output_tree(FILE *fout, const struct flame_node *node, - char *str, int maxlen, int base) +static int output_tree(FILE *fout, enum out_format_t out_format, + const struct flame_node *node, char *str, int maxlen, + int base) { const struct flame_node *child; int pos; - if (node->count) - fprintf(fout, "%s %d\n", str, node->count); + if (node->count) { + if (out_format == OUT_FMT_FLAMEGRAPH_CALLS) { + fprintf(fout, "%s %d\n", str, node->count); + } else { + /* + * Write out the number of microseconds used by this + * call stack. Since the time taken by child calls is + * subtracted from this total, it can reach 0, meaning + * that this function took no time beyond what its + * children used. For this case, write 1 rather than 0, + * so that this call stack appears in the flamegraph. + * This has the effect of inflating the timing slightly, + * but only by at most 1 microsecond per function, + * assuming that is the timestamp resolution + */ + fprintf(fout, "%s %ld\n", str, + node->duration ? node->duration : 1); + } + } pos = base; if (pos) @@ -1748,7 +1825,8 @@ static int output_tree(FILE *fout, const struct flame_node *node, return -1; } strcpy(str + pos, child->func->name); - if (output_tree(fout, child, str, maxlen, pos + len)) + if (output_tree(fout, out_format, child, str, maxlen, + pos + len)) return -1; } @@ -1759,18 +1837,19 @@ static int output_tree(FILE *fout, const struct flame_node *node, * make_flamegraph() - Write out a flame graph * * @fout: Output file + * @out_format: Output format to use, e.g. function counts or timing * Returns 0 if OK, -1 on error */ -static int make_flamegraph(FILE *fout) +static int make_flamegraph(FILE *fout, enum out_format_t out_format) { struct flame_node *tree; char str[500]; - if (make_flame_tree(&tree)) + if (make_flame_tree(out_format, &tree)) return -1; *str = '\0'; - if (output_tree(fout, tree, str, sizeof(str), 0)) + if (output_tree(fout, out_format, tree, str, sizeof(str), 0)) return -1; return 0; @@ -1822,13 +1901,16 @@ static int prof_tool(int argc, char *const argv[], } else if (!strcmp(cmd, "dump-flamegraph")) { FILE *fout; + if (out_format != OUT_FMT_FLAMEGRAPH_CALLS && + out_format != OUT_FMT_FLAMEGRAPH_TIMING) + out_format = OUT_FMT_FLAMEGRAPH_CALLS; fout = fopen(out_fname, "w"); if (!fout) { fprintf(stderr, "Cannot write file '%s'\n", out_fname); return -1; } - err = make_flamegraph(fout); + err = make_flamegraph(fout, out_format); fclose(fout); } else { warn("Unknown command '%s'\n", cmd); @@ -1858,6 +1940,10 @@ int main(int argc, char *argv[]) out_format = OUT_FMT_FUNCTION; } else if (!strcmp("funcgraph", optarg)) { out_format = OUT_FMT_FUNCGRAPH; + } else if (!strcmp("calls", optarg)) { + out_format = OUT_FMT_FLAMEGRAPH_CALLS; + } else if (!strcmp("timing", optarg)) { + out_format = OUT_FMT_FLAMEGRAPH_TIMING; } else { fprintf(stderr, "Invalid format: use function, funcgraph, calls, timing\n"); -- cgit v1.3.1 From 71d3e7949c652b87c33193ccbed36b9887c5b5c2 Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:15:59 -0700 Subject: Docker: Support trace-cmd Build trace-cmd as part of the docker image, so that trace tests can be used. Unfortunately the version provided by distributions is a little old and has bugs. It also does not support specifying the time base for the trace, which is required to convert microseconds to nanaseconds. Signed-off-by: Simon Glass --- tools/docker/Dockerfile | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/tools/docker/Dockerfile b/tools/docker/Dockerfile index 3d5a9a07447..aa19d924cc8 100644 --- a/tools/docker/Dockerfile +++ b/tools/docker/Dockerfile @@ -213,6 +213,22 @@ RUN git clone https://github.com/stefanberger/swtpm /tmp/swtpm && \ make install && \ rm -rf /tmp/swtpm +# Build trace-cmd +RUN mkdir /tmp/trace && \ + git clone https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git /tmp/trace/libtraceevent && \ + cd /tmp/trace/libtraceevent && \ + make -j$(nproc) && \ + sudo make install && \ + git clone https://git.kernel.org/pub/scm/libs/libtrace/libtracefs.git /tmp/trace/libtracefs && \ + cd /tmp/trace/libtracefs && \ + make -j$(nproc) && \ + sudo make install && \ + git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \ + cd /tmp/trace/trace-cmd && \ + make -j$(nproc) && \ + sudo make install && \ + rm -rf /tmp/trace + # Create our user/group RUN echo uboot ALL=NOPASSWD: ALL > /etc/sudoers.d/uboot RUN useradd -m -U uboot -- cgit v1.3.1 From 9cea4797aebcf952c95b503fc7aa6f1d422552bc Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:16:00 -0700 Subject: trace: Add a test Add a test which runs sandbox, collects a trace and makes sure it can be processed by trace-cmd. This should ensure that this feature continues to work as U-Boot and trace-cmd evolve. Signed-off-by: Simon Glass --- .azure-pipelines.yml | 8 ++ .gitlab-ci.yml | 12 ++ test/py/tests/test_trace.py | 304 ++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 324 insertions(+) create mode 100644 test/py/tests/test_trace.py diff --git a/.azure-pipelines.yml b/.azure-pipelines.yml index 5673bb76afb..74cc8dc60c0 100644 --- a/.azure-pipelines.yml +++ b/.azure-pipelines.yml @@ -240,6 +240,11 @@ stages: TEST_PY_TEST_SPEC: "test_ofplatdata or test_handoff or test_spl" sandbox_flattree: TEST_PY_BD: "sandbox_flattree" + sandbox_trace: + TEST_PY_BD: "sandbox" + BUILD_ENV: "FTRACE=1 NO_LTO=1" + TEST_PY_TEST_SPEC: "trace" + OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000" coreboot: TEST_PY_BD: "coreboot" TEST_PY_ID: "--id qemu" @@ -362,6 +367,9 @@ stages: # the below corresponds to .gitlab-ci.yml "script" cd ${WORK_DIR} export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD}; + if [ -n "${BUILD_ENV}" ]; then + export ${BUILD_ENV}; + fi tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e --board ${TEST_PY_BD} ${OVERRIDE} cp ~/grub_x86.efi ${UBOOT_TRAVIS_BUILD_DIR}/ cp ~/grub_x64.efi ${UBOOT_TRAVIS_BUILD_DIR}/ diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index aaf9d25abfc..382cb900456 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -35,6 +35,9 @@ stages: # If we've been asked to use clang only do one configuration. - export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD} - echo BUILD_ENV ${BUILD_ENV} + - if [ -n "${BUILD_ENV}" ]; then + export ${BUILD_ENV}; + fi - tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e --board ${TEST_PY_BD} ${OVERRIDE} - cp ~/grub_x86.efi $UBOOT_TRAVIS_BUILD_DIR/ @@ -268,6 +271,15 @@ sandbox_vpl test.py: TEST_PY_TEST_SPEC: "test_vpl_help or test_spl" <<: *buildman_and_testpy_dfn +# Enable tracing and disable LTO, to ensure functions are not elided +sandbox trace_test.py: + variables: + TEST_PY_BD: "sandbox" + BUILD_ENV: "FTRACE=1 NO_LTO=1" + TEST_PY_TEST_SPEC: "trace" + OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000" + <<: *buildman_and_testpy_dfn + evb-ast2500 test.py: variables: TEST_PY_BD: "evb-ast2500" diff --git a/test/py/tests/test_trace.py b/test/py/tests/test_trace.py new file mode 100644 index 00000000000..14584d11a23 --- /dev/null +++ b/test/py/tests/test_trace.py @@ -0,0 +1,304 @@ +# SPDX-License-Identifier: GPL-2.0 +# Copyright 2022 Google LLC +# Written by Simon Glass + +import os +import pytest +import re + +import u_boot_utils as util + +# This is needed for Azure, since the default '..' directory is not writeable +TMPDIR = '/tmp/test_trace' + +# Decode a function-graph line +RE_LINE = re.compile(r'.*\[000\]\s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$') + + +def collect_trace(cons): + """Build U-Boot and run it to collect a trace + + Args: + cons (ConsoleBase): U-Boot console + + Returns: + tuple: + str: Filename of the output trace file + int: Microseconds taken for initf_dm according to bootstage + """ + cons.run_command('trace pause') + out = cons.run_command('trace stats') + + # The output is something like this: + # 251,003 function sites + # 1,160,283 function calls + # 0 untracked function calls + # 1,230,758 traced function calls (341538 dropped due to overflow) + # 33 maximum observed call depth + # 15 call depth limit + # 748,268 calls not traced due to depth + # 1,230,758 max function calls + + # Get a dict of values from the output + lines = [line.split(maxsplit=1) for line in out.splitlines() if line] + vals = {key: val.replace(',', '') for val, key in lines} + + assert int(vals['function sites']) > 100000 + assert int(vals['function calls']) > 200000 + assert int(vals['untracked function calls']) == 0 + assert int(vals['maximum observed call depth']) > 30 + assert (vals['call depth limit'] == + cons.config.buildconfig.get('config_trace_call_depth_limit')) + assert int(vals['calls not traced due to depth']) > 100000 + + out = cons.run_command('bootstage report') + # Accumulated time: + # 19,104 dm_r + # 23,078 of_live + # 46,280 dm_f + dm_f_time = [line.split()[0] for line in out.replace(',', '').splitlines() + if 'dm_f' in line] + + # Read out the trace data + addr = 0x02000000 + size = 0x01000000 + out = cons.run_command(f'trace calls {addr:x} {size:x}') + print(out) + fname = os.path.join(TMPDIR, 'trace') + out = cons.run_command( + 'host save hostfs - %x %s ${profoffset}' % (addr, fname)) + return fname, int(dm_f_time[0]) + + +def check_function(cons, fname, proftool, map_fname, trace_dat): + """Check that the 'function' output works + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_dat (str): Filename of output file + """ + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname, + 'dump-ftrace']) + + # Check that trace-cmd can read it + out = util.run_and_log(cons, ['trace-cmd', 'dump', trace_dat]) + + # Tracing meta data in file /tmp/test_trace/trace.dat: + # [Initial format] + # 6 [Version] + # 0 [Little endian] + # 4 [Bytes in a long] + # 4096 [Page size, bytes] + # [Header page, 205 bytes] + # [Header event, 205 bytes] + # [Ftrace format, 3 events] + # [Events format, 0 systems] + # [Kallsyms, 342244 bytes] + # [Trace printk, 0 bytes] + # [Saved command lines, 9 bytes] + # 1 [CPUs with tracing data] + # [6 options] + # [Flyrecord tracing data] + # [Tracing clock] + # [local] global counter uptime perf mono mono_raw boot x86-tsc + assert '[Flyrecord tracing data]' in out + assert '4096 [Page size, bytes]' in out + kallsyms = [line.split() for line in out.splitlines() if 'Kallsyms' in line] + # [['[Kallsyms,', '342244', 'bytes]']] + val = int(kallsyms[0][1]) + assert val > 50000 # Should be at least 50KB of symbols + + # Check that the trace has something useful + cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_|initr_)'" + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + # Format: + # unknown option 14 + # u-boot-1 [000] 60.805596: function: initf_malloc + # u-boot-1 [000] 60.805597: function: initf_malloc + # u-boot-1 [000] 60.805601: function: initf_bootstage + # u-boot-1 [000] 60.805607: function: initf_bootstage + lines = [line.replace(':', '').split() for line in out.splitlines()] + vals = {items[4]: float(items[2]) for items in lines if len(items) == 5} + base = None + max_delta = 0 + for timestamp in vals.values(): + if base: + max_delta = max(max_delta, timestamp - base) + else: + base = timestamp + + # Check for some expected functions + assert 'initf_malloc' in vals.keys() + assert 'initr_watchdog' in vals.keys() + assert 'initr_dm' in vals.keys() + + # All the functions should be executed within five seconds at most + assert max_delta < 5 + + +def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): + """Check that the 'funcgraph' output works + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_dat (str): Filename of output file + + Returns: + int: Time taken by the first part of the initf_dm() function, in us + """ + + # Generate the funcgraph format + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname, + 'dump-ftrace', '-f', 'funcgraph']) + + # Check that the trace has what we expect + cmd = f'trace-cmd report {trace_dat} |head -n 70' + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + # First look for this: + # u-boot-1 [000] 282.101360: funcgraph_entry: 0.004 us | initf_malloc(); + # ... + # u-boot-1 [000] 282.101369: funcgraph_entry: | initf_bootstage() { + # u-boot-1 [000] 282.101369: funcgraph_entry: | bootstage_init() { + # u-boot-1 [000] 282.101369: funcgraph_entry: | dlmalloc() { + # ... + # u-boot-1 [000] 282.101375: funcgraph_exit: 0.001 us | } + # Then look for this: + # u-boot-1 [000] 282.101375: funcgraph_exit: 0.006 us | } + # Then check for this: + # u-boot-1 [000] 282.101375: funcgraph_entry: 0.000 us | event_init(); + + expected_indent = None + found_start = False + found_end = False + upto = None + + # Look for initf_bootstage() entry and make sure we see the exit + # Collect the time for initf_dm() + for line in out.splitlines(): + m = RE_LINE.match(line) + if m: + timestamp, indent, func, brace = m.groups() + if found_end: + upto = func + break + elif func == 'initf_bootstage() ': + found_start = True + expected_indent = indent + ' ' + elif found_start and indent == expected_indent and brace == '}': + found_end = True + + # The next function after initf_bootstage() exits should be event_init() + assert upto == 'event_init()' + + # Now look for initf_dm() and dm_timer_init() so we can check the bootstage + # time + cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_dm|dm_timer_init)'" + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + start_timestamp = None + end_timestamp = None + for line in out.splitlines(): + m = RE_LINE.match(line) + if m: + timestamp, indent, func, brace = m.groups() + if func == 'initf_dm() ': + start_timestamp = timestamp + elif func == 'dm_timer_init() ': + end_timestamp = timestamp + break + assert start_timestamp and end_timestamp + + # Convert the time to microseconds + return int((float(end_timestamp) - float(start_timestamp)) * 1000000) + + +def check_flamegraph(cons, fname, proftool, map_fname, trace_fg): + """Check that the 'flamegraph' output works + + This spot checks a few call counts and estimates the time taken by the + initf_dm() function + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_fg (str): Filename of output file + + Returns: + int: Approximate number of microseconds used by the initf_dm() function + """ + + # Generate the flamegraph format + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname, + 'dump-flamegraph']) + + # We expect dm_timer_init() to be called twice: once before relocation and + # once after + look1 = 'initf_dm;dm_timer_init 1' + look2 = 'board_init_r;initr_dm_devices;dm_timer_init 1' + found = 0 + with open(trace_fg, 'r') as fd: + for line in fd: + line = line.strip() + if line == look1 or line == look2: + found += 1 + assert found == 2 + + # Generate the timing graph + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname, + 'dump-flamegraph', '-f', 'timing']) + + # Add up all the time spend in initf_dm() and its children + total = 0 + with open(trace_fg, 'r') as fd: + for line in fd: + line = line.strip() + if line.startswith('initf_dm'): + func, val = line.split() + count = int(val) + total += count + return total + + +@pytest.mark.slow +@pytest.mark.boardspec('sandbox') +@pytest.mark.buildconfigspec('trace') +def test_trace(u_boot_console): + """Test we can build sandbox with trace, collect and process a trace""" + cons = u_boot_console + + if not os.path.exists(TMPDIR): + os.mkdir(TMPDIR) + proftool = os.path.join(cons.config.build_dir, 'tools', 'proftool') + map_fname = os.path.join(cons.config.build_dir, 'System.map') + trace_dat = os.path.join(TMPDIR, 'trace.dat') + trace_fg = os.path.join(TMPDIR, 'trace.fg') + + fname, dm_f_time = collect_trace(cons) + + check_function(cons, fname, proftool, map_fname, trace_dat) + trace_time = check_funcgraph(cons, fname, proftool, map_fname, trace_dat) + + # Check that bootstage and funcgraph agree to within 10 microseconds + diff = abs(trace_time - dm_f_time) + print(f'trace_time {trace_time}, dm_f_time {dm_f_time}') + assert diff / dm_f_time < 0.01 + + fg_time = check_flamegraph(cons, fname, proftool, map_fname, trace_fg) + + # Check that bootstage and flamegraph agree to within 10% + diff = abs(fg_time - dm_f_time) + assert diff / dm_f_time < 0.1 -- cgit v1.3.1 From e46b72436cab6d66fdb0263e0bf14082195b754e Mon Sep 17 00:00:00 2001 From: Simon Glass Date: Sun, 15 Jan 2023 14:16:01 -0700 Subject: trace: Update documentation Revamp the documentation for the new features, including a description of the new features and documentation for the trace command. Signed-off-by: Simon Glass --- .gitattributes | 1 + doc/develop/pics/flamegraph.png | Bin 0 -> 48224 bytes doc/develop/pics/flamegraph_timing.png | Bin 0 -> 31305 bytes doc/develop/pics/flamegraph_zoom.png | Bin 0 -> 25465 bytes doc/develop/pics/kernelshark.png | Bin 0 -> 29617 bytes doc/develop/pics/kernelshark_fg.png | Bin 0 -> 28899 bytes doc/develop/trace.rst | 281 +++++++++++++++++++++++++-------- doc/usage/cmd/trace.rst | 163 +++++++++++++++++++ doc/usage/index.rst | 1 + 9 files changed, 382 insertions(+), 64 deletions(-) create mode 100644 doc/develop/pics/flamegraph.png create mode 100644 doc/develop/pics/flamegraph_timing.png create mode 100644 doc/develop/pics/flamegraph_zoom.png create mode 100644 doc/develop/pics/kernelshark.png create mode 100644 doc/develop/pics/kernelshark_fg.png create mode 100644 doc/usage/cmd/trace.rst diff --git a/.gitattributes b/.gitattributes index 1879a2dfb3c..d5931f03e7c 100644 --- a/.gitattributes +++ b/.gitattributes @@ -4,3 +4,4 @@ *.bmp binary *.ttf binary *.gz binary +*.png binary diff --git a/doc/develop/pics/flamegraph.png b/doc/develop/pics/flamegraph.png new file mode 100644 index 00000000000..dbdd27e6d87 Binary files /dev/null and b/doc/develop/pics/flamegraph.png differ diff --git a/doc/develop/pics/flamegraph_timing.png b/doc/develop/pics/flamegraph_timing.png new file mode 100644 index 00000000000..b388b8b9881 Binary files /dev/null and b/doc/develop/pics/flamegraph_timing.png differ diff --git a/doc/develop/pics/flamegraph_zoom.png b/doc/develop/pics/flamegraph_zoom.png new file mode 100644 index 00000000000..38b68444b7b Binary files /dev/null and b/doc/develop/pics/flamegraph_zoom.png differ diff --git a/doc/develop/pics/kernelshark.png b/doc/develop/pics/kernelshark.png new file mode 100644 index 00000000000..3450c6b5fd3 Binary files /dev/null and b/doc/develop/pics/kernelshark.png differ diff --git a/doc/develop/pics/kernelshark_fg.png b/doc/develop/pics/kernelshark_fg.png new file mode 100644 index 00000000000..a54efd1c4cf Binary files /dev/null and b/doc/develop/pics/kernelshark_fg.png differ diff --git a/doc/develop/trace.rst b/doc/develop/trace.rst index 5c7802da51a..8425d843e9c 100644 --- a/doc/develop/trace.rst +++ b/doc/develop/trace.rst @@ -15,12 +15,16 @@ Overview The trace feature uses GCC's instrument-functions feature to trace all function entry/exit points. These are then recorded in a memory buffer. The memory buffer can be saved to the host over a network link using -tftpput or by writing to an attached memory device such as MMC. +tftpput or by writing to an attached storage device such as MMC. On the host, the file is first converted with a tool called 'proftool', which extracts useful information from it. The resulting trace output resembles that emitted by Linux's ftrace feature, so can be visually -displayed by pytimechart. +displayed by kernelshark (see kernelshark_) and used with +'trace-cmd report' (see trace_cmd_). + +It is also possible to produce a flame graph for use with flamegraph.pl +(see flamegraph_pl_). Quick-start using Sandbox @@ -30,7 +34,7 @@ Sandbox is a build of U-Boot that can run under Linux so it is a convenient way of trying out tracing before you use it on your actual board. To do this, follow these steps: -Add the following to config/sandbox_defconfig +Add the following to `config/sandbox_defconfig`: .. code-block:: c @@ -75,7 +79,7 @@ a trace: 16 maximum observed call depth 15 call depth limit 1,275,767 calls not traced due to depth - =>trace calls 0 e00000 + =>trace calls 1000000 e00000 Call list dumped to 00000000, size 0xae0a40 =>print baudrate=115200 @@ -87,7 +91,7 @@ a trace: stdout=serial Environment size: 117/8188 bytes - =>host save host 0 trace 0 ${profoffset} + =>host save hostfs - 1000000 trace ${profoffset} 11405888 bytes written in 10 ms (1.1 GiB/s) =>reset @@ -96,18 +100,107 @@ Then run proftool to convert the trace information to ftrace format .. code-block:: console - $ ./sandbox/tools/proftool -m sandbox/System.map -p trace dump-ftrace >trace.txt + $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-ftrace >trace.dat -Finally run pytimechart to display it +Finally run kernelshark to display it (note it only works with `.dat` files!): .. code-block:: console - $ pytimechart trace.txt + $ kernelshark trace.dat -Using this tool you can zoom and pan across the trace, with the function -calls on the left and little marks representing the start and end of each +Using this tool you can view the trace records and see the timestamp for each function. +.. image:: pics/kernelshark.png + :width: 800 + :alt: Kernelshark showing function-trace records + + +To see the records on the console, use trace-cmd: + +.. code-block:: console + + $ trace-cmd report trace.dat | less + cpus=1 + u-boot-1 [000] 3.116364: function: initf_malloc + u-boot-1 [000] 3.116375: function: initf_malloc + u-boot-1 [000] 3.116386: function: initf_bootstage + u-boot-1 [000] 3.116396: function: bootstage_init + u-boot-1 [000] 3.116408: function: malloc + u-boot-1 [000] 3.116418: function: malloc_simple + u-boot-1 [000] 3.116429: function: alloc_simple + u-boot-1 [000] 3.116441: function: alloc_simple + u-boot-1 [000] 3.116449: function: malloc_simple + u-boot-1 [000] 3.116457: function: malloc + +Note that `pytimechart` is obsolete so cannot be used anymore. + +There is a -f option available to select a function graph: + +.. code-block:: console + + $ ./sandbox/tools/proftool -m sandbox/System.map -t trace -f funcgraph dump-ftrace >trace.dat + +Again, you can use kernelshark or trace-cmd to look at the output. In this case +you will see the time taken by each function shown against its exit record. + +.. image:: pics/kernelshark_fg.png + :width: 800 + :alt: Kernelshark showing function-graph records + +.. code-block:: console + + $ trace-cmd report trace.dat | less + cpus=1 + u-boot-1 [000] 3.116364: funcgraph_entry: 0.011 us | initf_malloc(); + u-boot-1 [000] 3.116386: funcgraph_entry: | initf_bootstage() { + u-boot-1 [000] 3.116396: funcgraph_entry: | bootstage_init() { + u-boot-1 [000] 3.116408: funcgraph_entry: | malloc() { + u-boot-1 [000] 3.116418: funcgraph_entry: | malloc_simple() { + u-boot-1 [000] 3.116429: funcgraph_entry: 0.012 us | alloc_simple(); + u-boot-1 [000] 3.116449: funcgraph_exit: 0.031 us | } + u-boot-1 [000] 3.116457: funcgraph_exit: 0.049 us | } + u-boot-1 [000] 3.116466: funcgraph_entry: 0.063 us | memset(); + u-boot-1 [000] 3.116539: funcgraph_exit: 0.143 us | } + +Flame graph +----------- + +Some simple flame graph options are available as well, using the dump-flamegraph +command: + +.. code-block:: console + + $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-flamegraph >trace.fg + $ flamegraph.pl trace.fg >trace.svg + +You can load the .svg file into a viewer. If you use Chrome (and some other +programs) you can click around and zoom in and out. + +.. image:: pics/flamegraph.png + :width: 800 + :alt: Chrome showing the flamegraph.pl output + +.. image:: pics/flamegraph_zoom.png + :width: 800 + :alt: Chrome showing zooming into the flamegraph.pl output + + +A timing variant is also available, which gives an idea of how much time is +spend in each call stack: + +.. code-block:: console + + $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-flamegraph -f timing >trace.fg + $ flamegraph.pl trace.fg >trace.svg + +Note that trace collection does slow down execution so the timings will be +inflated. They should be used to guide optimisation. For accurate boot timings, +use bootstage. + +.. image:: pics/flamegraph_timing.png + :width: 800 + :alt: Chrome showing flamegraph.pl output with timing CONFIG Options -------------- @@ -138,6 +231,11 @@ CONFIG_TRACE_EARLY_SIZE CONFIG_TRACE_EARLY_ADDR Address of early trace buffer +CONFIG_TRACE_CALL_DEPTH_LIMIT + Sets the limit on trace call-depth. For a broad view, 10 is typically + sufficient. Setting this too large creates enormous traces and distorts + the overall timing considerable. + Building U-Boot with Tracing Enabled ------------------------------------ @@ -148,6 +246,26 @@ instrumenting from the command line instead of having to change board config files. +Board requirements +------------------ + +Trace data collection relies on a microsecond timer, accessed through +`timer_get_us()`. So the first thing you should do is make sure that +this produces sensible results for your board. Suitable sources for +this timer include high resolution timers, PWMs or profile timers if +available. Most modern SOCs have a suitable timer for this. + +See `add_ftrace()` for where `timer_get_us()` is called. The `notrace` +attribute must be used on each function called by `timer_get_us()` since +recursive calls to `add_ftrace()` will cause a fault:: + + trace: recursion detected, disabling + +You cannot use driver model to obtain the microsecond timer, since tracing +may be enabled before driver model is set up. Instead, provide a low-level +function which accesses the timer, setting it up if needed. + + Collecting Trace Data --------------------- @@ -155,21 +273,22 @@ When you run U-Boot on your board it will collect trace data up to the limit of the trace buffer size you have specified. Once that is exhausted no more data will be collected. -Collecting trace data has an affect on execution time/performance. You +Collecting trace data affects execution time and performance. You will notice this particularly with trivial functions - the overhead of recording their execution may even exceed their normal execution time. In practice this doesn't matter much so long as you are aware of the effect. Once you have done your optimizations, turn off tracing before -doing end-to-end timing. +doing end-to-end timing using bootstage. The best time to start tracing is right at the beginning of U-Boot. The best time to stop tracing is right at the end. In practice it is hard to achieve these ideals. -This implementation enables tracing early in board_init_f(). This means +This implementation enables tracing early in `board_init_r()`, or +`board_init_f()` when `TRACE_EARLY` is enabled. This means that it captures most of the board init process, missing only the early architecture-specific init. However, it also misses the entire -SPL stage if there is one. +SPL stage if there is one. At present tracing is not supported in SPL. U-Boot typically ends with a 'bootm' command which loads and runs an OS. There is useful trace data in the execution of that bootm @@ -179,39 +298,11 @@ the OS. In practical terms, U-Boot runs the 'fakegocmd' environment variable at this point. This variable should have a short script which collects the trace data and writes it somewhere. -Trace data collection relies on a microsecond timer, accessed through -timer_get_us(). So the first think you should do is make sure that -this produces sensible results for your board. Suitable sources for -this timer include high resolution timers, PWMs or profile timers if -available. Most modern SOCs have a suitable timer for this. Make sure -that you mark this timer (and anything it calls) with -notrace so that the trace library can -use it without causing an infinite loop. - - -Commands --------- - -The trace command has variable sub-commands: - -stats - Display tracing statistics - -pause - Pause tracing - -resume - Resume tracing - -funclist [ ] - Dump a list of functions into the buffer - -calls [ ] - Dump function call trace into buffer +Controlling the trace +--------------------- -If the address and size are not given, these are obtained from environment -variables (see below). In any case the environment variables are updated -after the command runs. +U-Boot provides a command-line interface to the trace system for controlling +tracing and accessing the trace data. See :doc:`../usage/cmd/trace`. Environment Variables @@ -264,39 +355,94 @@ a trace log to address 10000000 and sends it to a host machine using TFTP. After this, U-Boot will boot the OS normally, albeit a little later. +For a filesystem you may do something like:: + + trace calls 10000000 1000000; + save mmc 1:1 10000000 /trace ${profoffset} + +The trace buffer format is internal to the trace system. It consists of a +header, a call count for each function site, followed by a list of trace +records, once for each function call. + -Converting Trace Output Data ----------------------------- +Converting Trace Output Data (proftool) +--------------------------------------- The trace output data is kept in a binary format which is not documented -here. To convert it into something useful, you can use proftool. +here. See the `trace.h` header file if you are interested. To convert it into +something useful, you can use proftool. This tool must be given the U-Boot map file and the trace data received -from running that U-Boot. It produces a text output file. +from running that U-Boot. It produces a binary output file. + +It is also possible to provide a configuration file to indicate which functions +should be included or dropped during conversion. This file consists of lines +like:: + + include-func + exclude-func -Options +where is a regular expression matched against function names. It +allows some functions to be dropped from the trace when producing ftrace +records. + +Options: + +-c + Specify the optional configuration file, to control which functions are + included in the output. + +-f + Specifies the format to use (see below) -m - Specify U-Boot map file + Specify U-Boot map file (`System.map`) + +-o + Specify the output filename --p - Specify profile/trace file +-t + Specify trace file, the data saved from U-Boot + +-v <0-4> + Specify the verbosity, where 0 is the minimum and 4 is for debugging. Commands: -dump-ftrace - Write a text dump of the file in Linux ftrace format to stdout +dump-ftrace: + Write a binary dump of the file in Linux ftrace format. Two options are + available: + + function + write function-call records (caller/callee) + + funcgraph + write function entry/exit records (graph) + + This format can be used with kernelshark_ and trace_cmd_. + +dump-flamegraph + Write a list of stack records useful for producing a flame graph. Two + options are available: + calls + create a flamegraph of stack frames + + timing + create a flamegraph of microseconds for each stack frame + + This format can be used with flamegraph_pl_. Viewing the Trace Data ---------------------- -You can use pytimechart for this (sudo apt-get pytimechart might work on -your Debian-style machine, and use your favourite search engine to obtain -documentation). It expects the file to have a .txt extension. The program -has terse user interface but is very convenient for viewing U-Boot -profile information. +You can use kernelshark_ for a GUI, but note that version 2.0.x was broken. If +you have that version you could try building it from source. +The file must have a .dat extension or it is ignored. The program has terse +user interface but is very convenient for viewing U-Boot profile information. + +Also available is trace_cmd_ which provides a command-line interface. Workflow Suggestions -------------------- @@ -329,7 +475,9 @@ There are a few parameters in the code that you may want to consider. There is a function call depth limit (set to 15 by default). When the stack depth goes above this then no tracing information is recorded. The maximum depth reached is recorded and displayed by the 'trace stats' -command. +command. While it might be tempting to set the depth limit quite high, this +can dramatically increase the size of the trace output as well as the execution +time. Future Work @@ -346,5 +494,10 @@ Some other features that might be useful: - Compression of trace information -Simon Glass -April 2013 +.. sectionauthor:: Simon Glass +.. April 2013 +.. Updated January 2023 + +.. _kernelshark: https://kernelshark.org/ +.. _trace_cmd: https://www.trace-cmd.org/ +.. _flamegraph_pl: https://github.com/brendangregg/FlameGraph/blob/master/flamegraph.pl diff --git a/doc/usage/cmd/trace.rst b/doc/usage/cmd/trace.rst new file mode 100644 index 00000000000..3bdf4f0a860 --- /dev/null +++ b/doc/usage/cmd/trace.rst @@ -0,0 +1,163 @@ +.. SPDX-License-Identifier: GPL-2.0+: + +trace command +============= + +Synopis +------- + +:: + + trace stats + trace pause + trace resume + trace funclist [ ] + trace calls [ ] + +Description +----------- + +The *trace* command is used to control the U-Boot tracing system. It allows +tracing to be paused and resumed, shows statistics for traces and provides a +way to dump out the trace information. + + +trace stats +~~~~~~~~~~~ + +This display tracing statistics, as follows: + +function sites + Functions are binned as a way of reducing the amount of space needed to + hold all the function information. This is controlled by FUNC_SITE_SIZE in + the trace.h header file. The usual value is 4, which provides the finest + granularity (assuming a minimum instruction size of 4 bytes) which means + that every function can be resolved individually. + +function calls + Total number of function calls, including those which were not traced due + to buffer space. This count does not include functions which exceeded the + depth limit. + +untracked function calls + Total number of function calls which did not appear in the U-Boot image. + This can happen if a function is called outside the normal code area. + +traced function calls + Total number of function calls which were actually traced, i.e. are included + in the recorded trace data. + +dropped due to overflow + If the trace buffer was exhausted then this shows the number of records that + were dropped. Try reducing the depth limit or expanding the buffer size. + +maximum observed call depth + Maximum observed call depth while tracing. + +calls not traced due to depth + Counts the number of function calls that were not recorded because they + exceeded the maximum call depth. + +max function calls + Maximum number of function calls which can be recorded in the trace buffer, + given its size. Once `function calls` hits this value, recording stops. + +trace buffer + Address of trace buffer + +call records + Address of first trace record. This is near the start of the trace buffer, + after the function-call counts. + + +trace pause +~~~~~~~~~~~ + +Pauses tracing, so that no more data is added to the trace buffer. + + +trace resume +~~~~~~~~~~~~ + +Resumes tracing, so that new function calls are added to the trace buffer if +there is sufficient space. + + +trace funclist [ ] +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +Dumps a list of functions into the provided buffer. The file uses a format +specific to U-Boot: a header, following by the function offset and call count. + +If the address and size are not given, these are obtained from +:ref:`develop/trace:environment variables`. In any case the environment +variables are updated after the command runs. + +The resulting data should be written out to the host, e.g. using Ethernet or +a filesystem. There are no tools provided to read this sdata. + + +trace calls [ ] +~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +Dumps a list of function calls into the provided buffer. The file uses a format +specific to U-Boot: a header, following by the list of calls. The proftool +tool can be used to convert this information ready for further analysis. + + +Example +------- + +:: + + => trace stats + 269,252 function sites + 38,025,059 function calls + 3 untracked function calls + 7,382,690 traced function calls + 17 maximum observed call depth + 15 call depth limit + 68,667,432 calls not traced due to depth + 22,190,112 max function calls + + trace buffer 6c000000 call records 6c20de78 + => trace resume + => trace pause + +This shows that resuming the trace causes the buffer to overflow:: + + => trace stats + 269,252 function sites + 49,573,694 function calls + 3 untracked function calls + 22,190,112 traced function calls (8289848 dropped due to overflow) + 17 maximum observed call depth + 15 call depth limit + 68,667,432 calls not traced due to depth + 22,190,112 max function calls + + trace buffer 6c000000 call records 6c20de78 + => trace funcs 30000000 0x100000 + Function trace dumped to 30000000, size 0x1e70 + +This shows collecting and writing out the result trace data: + +:: + => trace calls 20000000 0x10000000 + Call list dumped to 20000000, size 0xfdf21a0 + => save mmc 1:1 20000000 /trace ${profoffset} + File System is consistent + file found, deleting + update journal finished + File System is consistent + update journal finished + 266281376 bytes written in 18584 ms (13.7 MiB/s) + +From here you can use proftool to convert it: + +.. code-block:: bash + + tools/proftool -m System.map -t trace -o asc.fg dump-ftrace + + +.. _`ACPI specification`: https://uefi.org/sites/default/files/resources/ACPI_6_3_final_Jan30.pdf diff --git a/doc/usage/index.rst b/doc/usage/index.rst index 13e6939b38d..cde7dcb14a6 100644 --- a/doc/usage/index.rst +++ b/doc/usage/index.rst @@ -84,6 +84,7 @@ Shell commands cmd/sm cmd/temperature cmd/tftpput + cmd/trace cmd/true cmd/ums cmd/ut -- cgit v1.3.1 From 16bf3b6f8f35c295419dab9fc698d50686592f9c Mon Sep 17 00:00:00 2001 From: Tom Rini Date: Tue, 7 Feb 2023 12:32:19 -0500 Subject: CI, Docker: Update to Jammy 2023016 tag Move to the latest tag for "Jammy" and rebuild the containers. Signed-off-by: Tom Rini --- .azure-pipelines.yml | 2 +- .gitlab-ci.yml | 2 +- tools/docker/Dockerfile | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.azure-pipelines.yml b/.azure-pipelines.yml index 74cc8dc60c0..947c400f8d3 100644 --- a/.azure-pipelines.yml +++ b/.azure-pipelines.yml @@ -2,7 +2,7 @@ variables: windows_vm: windows-2019 ubuntu_vm: ubuntu-22.04 macos_vm: macOS-12 - ci_runner_image: trini/u-boot-gitlab-ci-runner:jammy-20221130-11Jan2023 + ci_runner_image: trini/u-boot-gitlab-ci-runner:jammy-20230126-10Feb2023 # Add '-u 0' options for Azure pipelines, otherwise we get "permission # denied" error when it tries to "useradd -m -u 1001 vsts_azpcontainer", # since our $(ci_runner_image) user is not root. diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 382cb900456..272d69e2206 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -2,7 +2,7 @@ # Grab our configured image. The source for this is found # in the u-boot tree at tools/docker/Dockerfile -image: trini/u-boot-gitlab-ci-runner:jammy-20221130-11Jan2023 +image: trini/u-boot-gitlab-ci-runner:jammy-20230126-10Feb2023 # We run some tests in different order, to catch some failures quicker. stages: diff --git a/tools/docker/Dockerfile b/tools/docker/Dockerfile index aa19d924cc8..33e2bd2add6 100644 --- a/tools/docker/Dockerfile +++ b/tools/docker/Dockerfile @@ -2,7 +2,7 @@ # This Dockerfile is used to build an image containing basic stuff to be used # to build U-Boot and run our test suites. -FROM ubuntu:jammy-20221130 +FROM ubuntu:jammy-20230126 MAINTAINER Tom Rini LABEL Description=" This image is for building U-Boot inside a container" -- cgit v1.3.1