From 611ddae2a543f846e29d194ca03f8db598f77fa7 Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 13:05:17 +0300 Subject: [PATCH 1/7] profiling: Add perf tool Add profiling subsystem. Add perf util based on periodic stack unwinding. Perf from Linux was taken as a reference. The operation of module is based on frame pointer usage and saving registers during interruption handling. The unwinding function stay in timer as expiry functioin so is called during interruption handling. Thus the function have access to saved registers (program counter and frame pointer in particular) of the current thread and use it to unwind the thread stack. Timer starting and results printing function are made as shell commands for conveniency. Originally-by: Yonatan Goldschmidt Signed-off-by: Mikhail Kushnerov --- subsys/CMakeLists.txt | 1 + subsys/Kconfig | 1 + subsys/profiling/CMakeLists.txt | 5 + subsys/profiling/Kconfig | 14 +++ subsys/profiling/perf/CMakeLists.txt | 5 + subsys/profiling/perf/Kconfig | 23 +++++ subsys/profiling/perf/perf.c | 145 +++++++++++++++++++++++++++ 7 files changed, 194 insertions(+) create mode 100644 subsys/profiling/CMakeLists.txt create mode 100644 subsys/profiling/Kconfig create mode 100644 subsys/profiling/perf/CMakeLists.txt create mode 100644 subsys/profiling/perf/Kconfig create mode 100644 subsys/profiling/perf/perf.c diff --git a/subsys/CMakeLists.txt b/subsys/CMakeLists.txt index 584559fa50e67..58f0cf6ffc3e2 100644 --- a/subsys/CMakeLists.txt +++ b/subsys/CMakeLists.txt @@ -48,6 +48,7 @@ add_subdirectory_ifdef(CONFIG_JWT jwt) add_subdirectory_ifdef(CONFIG_LLEXT llext) add_subdirectory_ifdef(CONFIG_MODEM_MODULES modem) add_subdirectory_ifdef(CONFIG_NET_BUF net) +add_subdirectory_ifdef(CONFIG_PROFILING profiling) add_subdirectory_ifdef(CONFIG_RETENTION retention) add_subdirectory_ifdef(CONFIG_SENSING sensing) add_subdirectory_ifdef(CONFIG_SETTINGS settings) diff --git a/subsys/Kconfig b/subsys/Kconfig index 2c708e26d59ec..59c7fa1721018 100644 --- a/subsys/Kconfig +++ b/subsys/Kconfig @@ -33,6 +33,7 @@ source "subsys/modem/Kconfig" source "subsys/net/Kconfig" source "subsys/pm/Kconfig" source "subsys/portability/Kconfig" +source "subsys/profiling/Kconfig" source "subsys/random/Kconfig" source "subsys/retention/Kconfig" source "subsys/rtio/Kconfig" diff --git a/subsys/profiling/CMakeLists.txt b/subsys/profiling/CMakeLists.txt new file mode 100644 index 0000000000000..223d049486c2d --- /dev/null +++ b/subsys/profiling/CMakeLists.txt @@ -0,0 +1,5 @@ +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +add_subdirectory_ifdef(CONFIG_PROFILING_PERF perf) diff --git a/subsys/profiling/Kconfig b/subsys/profiling/Kconfig new file mode 100644 index 0000000000000..6239b974ca35b --- /dev/null +++ b/subsys/profiling/Kconfig @@ -0,0 +1,14 @@ +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +menuconfig PROFILING + bool "Profiling tools" + help + Enable profiling tools, such as perf + +if PROFILING + +source "subsys/profiling/perf/Kconfig" + +endif diff --git a/subsys/profiling/perf/CMakeLists.txt b/subsys/profiling/perf/CMakeLists.txt new file mode 100644 index 0000000000000..4ab7b625d7281 --- /dev/null +++ b/subsys/profiling/perf/CMakeLists.txt @@ -0,0 +1,5 @@ +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +zephyr_sources(perf.c) diff --git a/subsys/profiling/perf/Kconfig b/subsys/profiling/perf/Kconfig new file mode 100644 index 0000000000000..b9d58f6f20f7d --- /dev/null +++ b/subsys/profiling/perf/Kconfig @@ -0,0 +1,23 @@ +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +config PROFILING_PERF + bool "Perf support" + depends on THREAD_STACK_INFO + depends on !SMP + depends on FRAME_POINTER + depends on SHELL + depends on RISCV || X86 + help + Enable perf shell command. + +if PROFILING_PERF + +config PROFILING_PERF_BUFFER_SIZE + int "Perf buffer size" + default 2048 + help + Size of buffer, that used by perf to save samples from stack tracing. + +endif diff --git a/subsys/profiling/perf/perf.c b/subsys/profiling/perf/perf.c new file mode 100644 index 0000000000000..e0c0dcba79359 --- /dev/null +++ b/subsys/profiling/perf/perf.c @@ -0,0 +1,145 @@ +/* + * Copyright (c) 2023 KNS Group LLC (YADRO) + * Copyright (c) 2020 Yonatan Goldschmidt + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include +#include +#include +#include + +size_t arch_perf_current_stack_trace(uintptr_t *buf, size_t size); + +struct perf_data_t { + struct k_timer timer; + + const struct shell *sh; + + struct k_work_delayable dwork; + + size_t idx; + uintptr_t buf[CONFIG_PROFILING_PERF_BUFFER_SIZE]; + bool buf_full; +}; + +#define PERF_EVENT_TRACING_BUF_OVERFLOW (1 << 0) + +static struct perf_data_t perf_data = { + .idx = 0, +}; + +static void perf_tracer(struct k_timer *timer) +{ + struct perf_data_t *perf_data_ptr = + (struct perf_data_t *)k_timer_user_data_get(timer); + + size_t trace_length = 0; + + if (++perf_data_ptr->idx < CONFIG_PROFILING_PERF_BUFFER_SIZE) { + trace_length = arch_perf_current_stack_trace( + perf_data_ptr->buf + perf_data_ptr->idx, + CONFIG_PROFILING_PERF_BUFFER_SIZE - perf_data_ptr->idx); + } + + if (trace_length != 0) { + perf_data_ptr->buf[perf_data_ptr->idx - 1] = trace_length; + perf_data_ptr->idx += trace_length; + } else { + --perf_data_ptr->idx; + perf_data_ptr->buf_full = true; + k_timer_stop(timer); + k_work_reschedule(&perf_data_ptr->dwork, K_NO_WAIT); + } +} + +static void perf_dwork_handler(struct k_work *work) +{ + struct k_work_delayable *dwork = k_work_delayable_from_work(work); + struct perf_data_t *perf_data_ptr = CONTAINER_OF(dwork, struct perf_data_t, dwork); + + if (perf_data_ptr->buf_full) { + shell_error(perf_data_ptr->sh, "Perf buf overflow!"); + } else { + k_timer_stop(&perf_data_ptr->timer); + shell_print(perf_data_ptr->sh, "Perf done!"); + } +} + +static int perf_init(void) +{ + k_timer_init(&perf_data.timer, perf_tracer, NULL); + k_work_init_delayable(&perf_data.dwork, perf_dwork_handler); + + return 0; +} + +int cmd_perf_record(const struct shell *sh, size_t argc, char **argv) +{ + if (k_work_delayable_is_pending(&perf_data.dwork)) { + shell_warn(sh, "Perf is already running"); + return -EINPROGRESS; + } + + if (perf_data.buf_full) { + shell_warn(sh, "Perf buffer is full"); + return -ENOBUFS; + } + + k_timeout_t duration = K_MSEC(strtoll(argv[1], NULL, 10)); + k_timeout_t period = K_NSEC(1000000000 / strtoll(argv[2], NULL, 10)); + + perf_data.sh = sh; + + k_timer_user_data_set(&perf_data.timer, &perf_data); + k_timer_start(&perf_data.timer, K_NO_WAIT, period); + + k_work_schedule(&perf_data.dwork, duration); + + shell_print(sh, "Enabled perf"); + + return 0; +} + +int cmd_perf_print(const struct shell *sh, size_t argc, char **argv) +{ + if (k_work_delayable_is_pending(&perf_data.dwork)) { + shell_warn(sh, "Perf is already running"); + return -EINPROGRESS; + } + + shell_print(sh, "Perf buf length %zu", perf_data.idx); + for (size_t i = 0; i < perf_data.idx; i++) { + shell_print(sh, "%016lx", perf_data.buf[i]); + } + + perf_data.idx = 0; + + return 0; +} + +static int cmd_perf(const struct shell *sh, size_t argc, char **argv) +{ + ARG_UNUSED(argc); + ARG_UNUSED(argv); + + shell_print(sh, "perfy"); + return 0; +} + +#define CMD_HELP_RECORD \ + "Start recording for ms on Hz\n" \ + "Usage: record \n" + +SHELL_STATIC_SUBCMD_SET_CREATE(m_sub_perf, + SHELL_CMD_ARG(record, NULL, CMD_HELP_RECORD, cmd_perf_record, 3, 0), + SHELL_CMD_ARG(printbuf, NULL, "Print the perf buffer", cmd_perf_print, 0, 0), + SHELL_SUBCMD_SET_END +); +SHELL_CMD_ARG_REGISTER(perf, &m_sub_perf, "Perf!", cmd_perf, 0, 0); + +SYS_INIT(perf_init, APPLICATION, 0); From 13156ada261f3cc1a8ce263eda547e50f0155da1 Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 14:16:31 +0300 Subject: [PATCH 2/7] arch: riscv: Implement perf stack thrace func Implement stack trace function for riscv arch, that get required thread register values and unwind stack with it. Signed-off-by: Mikhail Kushnerov --- arch/riscv/core/CMakeLists.txt | 1 + arch/riscv/core/perf.c | 93 ++++++++++++++++++++++++++++++++++ 2 files changed, 94 insertions(+) create mode 100644 arch/riscv/core/perf.c diff --git a/arch/riscv/core/CMakeLists.txt b/arch/riscv/core/CMakeLists.txt index 74d520458ad20..72bdee174d1e9 100644 --- a/arch/riscv/core/CMakeLists.txt +++ b/arch/riscv/core/CMakeLists.txt @@ -27,3 +27,4 @@ zephyr_library_sources_ifdef(CONFIG_USERSPACE userspace.S) zephyr_library_sources_ifdef(CONFIG_SEMIHOST semihost.c) zephyr_library_sources_ifdef(CONFIG_EXCEPTION_STACK_TRACE stacktrace.c) zephyr_linker_sources(ROM_START SORT_KEY 0x0vectors vector_table.ld) +zephyr_library_sources_ifdef(CONFIG_PROFILING_PERF perf.c) diff --git a/arch/riscv/core/perf.c b/arch/riscv/core/perf.c new file mode 100644 index 0000000000000..43de474eb6f93 --- /dev/null +++ b/arch/riscv/core/perf.c @@ -0,0 +1,93 @@ +/* + * Copyright (c) 2023 KNS Group LLC (YADRO) + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include + +static bool valid_stack(uintptr_t addr, k_tid_t current) +{ + return current->stack_info.start <= addr && + addr < current->stack_info.start + current->stack_info.size; +} + +/* + * This function use frame pointers to unwind stack and get trace of return addresses. + * Return addresses are translated in corresponding function's names using .elf file. + * So we get function call trace + */ +size_t arch_perf_current_stack_trace(uintptr_t *buf, size_t size) +{ + if (size < 2U) + return 0; + + size_t idx = 0; + + /* + * In riscv (arch/riscv/core/isr.S) ra, ip($mepc) and fp($s0) are saved + * at the beginning of _isr_wrapper in order, specified by z_arch_esf_t. + * Then, before calling interruption handler, core switch $sp to + * _current_cpu->irq_stack and save $sp with offset -16 on irq stack + * + * The following lines lines do the reverse things to get ra, ip anf fp + * from thread stack + */ + const struct arch_esf * const esf = + *((struct arch_esf **)(((uintptr_t)_current_cpu->irq_stack) - 16)); + + /* + * $s0 is used as frame pointer. + * + * stack frame in memory (commonly): + * (addresses growth up) + * .... + * [-] <- $fp($s0) (curr) + * $ra + * $fp($s0) (next) + * .... + * + * If function do not call any other function, compiller may not save $ra, + * then stack frame will be: + * .... + * [-] <- $fp($s0) (curr) + * $fp($s0) (next) + * .... + * + */ + void **fp = (void **)esf->s0; + void **new_fp = (void **)fp[-1]; + + buf[idx++] = (uintptr_t)esf->mepc; + + /* + * During function prologue and epilogue fp is equal to fp of + * previous function stack frame, it looks like second function + * from top is missed. + * So saving $ra will help in case when irq occurred in + * function prologue or epilogue. + */ + buf[idx++] = (uintptr_t)esf->ra; + if (valid_stack((uintptr_t)new_fp, _current)) { + fp = new_fp; + } + while (valid_stack((uintptr_t)fp, _current)) { + if (idx >= size) + return 0; + + buf[idx++] = (uintptr_t)fp[-1]; + new_fp = (void **)fp[-2]; + + /* + * anti-infinity-loop if + * new_fp can't be smaller than fp, cause the stack is growing down + * and trace moves deeper into the stack + */ + if (new_fp <= fp) { + break; + } + fp = new_fp; + } + + return idx; +} From 73433502a0814299e958c63ab8f3331d4ab6c5d4 Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 14:27:44 +0300 Subject: [PATCH 3/7] arch: x86: intel64: make perf stack thrace func Implement stack trace function for x86_64 arch, that get required thread register values and unwind stack with it. Originally-by: Yonatan Goldschmidt Signed-off-by: Mikhail Kushnerov --- arch/x86/core/intel64.cmake | 1 + arch/x86/core/intel64/perf.c | 67 ++++++++++++++++++++++++++++++++++++ 2 files changed, 68 insertions(+) create mode 100644 arch/x86/core/intel64/perf.c diff --git a/arch/x86/core/intel64.cmake b/arch/x86/core/intel64.cmake index 1cb25ebe220e5..dd3bb38af7a09 100644 --- a/arch/x86/core/intel64.cmake +++ b/arch/x86/core/intel64.cmake @@ -20,3 +20,4 @@ zephyr_library_sources_ifdef(CONFIG_IRQ_OFFLOAD intel64/irq_offload.c) zephyr_library_sources_ifdef(CONFIG_USERSPACE intel64/userspace.S) zephyr_library_sources_ifdef(CONFIG_THREAD_LOCAL_STORAGE intel64/tls.c) zephyr_library_sources_ifdef(CONFIG_DEBUG_COREDUMP intel64/coredump.c) +zephyr_library_sources_ifdef(CONFIG_PROFILING_PERF intel64/perf.c) diff --git a/arch/x86/core/intel64/perf.c b/arch/x86/core/intel64/perf.c new file mode 100644 index 0000000000000..754450100ab5d --- /dev/null +++ b/arch/x86/core/intel64/perf.c @@ -0,0 +1,67 @@ +/* + * Copyright (c) 2023 KNS Group LLC (YADRO) + * Copyright (c) 2020 Yonatan Goldschmidt + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include + +static bool valid_stack(uintptr_t addr, k_tid_t current) +{ + return current->stack_info.start <= addr && + addr < current->stack_info.start + current->stack_info.size; +} + +/* + * This function use frame pointers to unwind stack and get trace of return addresses. + * Return addresses are translated in corresponding function's names using .elf file. + * So we get function call trace + */ +size_t arch_perf_current_stack_trace(uintptr_t *buf, size_t size) +{ + if (size < 1U) + return 0; + + size_t idx = 0; + + /* + * In x86_64 (arch/x86/core/intel64/locore.S) %rip and %rbp + * are always saved in _current->callee_saved before calling + * handler function if interrupt is not nested + * + * %rip points the location where interrupt was occurred + */ + buf[idx++] = (uintptr_t)_current->callee_saved.rip; + void **fp = (void **)_current->callee_saved.rbp; + + /* + * %rbp is frame pointer. + * + * stack frame in memory: + * (addresses growth up) + * .... + * ra + * %rbp (next) <- %rbp (curr) + * .... + */ + while (valid_stack((uintptr_t)fp, _current)) { + if (idx >= size) + return 0; + + buf[idx++] = (uintptr_t)fp[1]; + void **new_fp = (void **)fp[0]; + + /* + * anti-infinity-loop if + * new_fp can't be smaller than fp, cause the stack is growing down + * and trace moves deeper into the stack + */ + if (new_fp <= fp) { + break; + } + fp = new_fp; + } + + return idx; +} From 91364721992ba59c49f3c7b3c234a6c75d2ac19a Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 4 Jul 2024 12:39:28 +0300 Subject: [PATCH 4/7] arch: x86: ia32: Implement perf stack thrace func Implement stack trace function for x86_32 arch, that get required thread register values and unwind stack with it. Signed-off-by: Mikhail Kushnerov --- arch/x86/core/ia32.cmake | 2 + arch/x86/core/ia32/intstub.S | 15 +++---- arch/x86/core/ia32/perf.c | 81 ++++++++++++++++++++++++++++++++++++ 3 files changed, 91 insertions(+), 7 deletions(-) create mode 100644 arch/x86/core/ia32/perf.c diff --git a/arch/x86/core/ia32.cmake b/arch/x86/core/ia32.cmake index 48207011b5009..64617f56b39f4 100644 --- a/arch/x86/core/ia32.cmake +++ b/arch/x86/core/ia32.cmake @@ -25,6 +25,8 @@ zephyr_library_sources_ifdef(CONFIG_GDBSTUB ia32/gdbstub.c) zephyr_library_sources_ifdef(CONFIG_DEBUG_COREDUMP ia32/coredump.c) +zephyr_library_sources_ifdef(CONFIG_PROFILING_PERF ia32/perf.c) + zephyr_library_sources_ifdef( CONFIG_X86_USE_THREAD_LOCAL_STORAGE ia32/tls.c diff --git a/arch/x86/core/ia32/intstub.S b/arch/x86/core/ia32/intstub.S index 4cd5c0bee9040..dd454670dd886 100644 --- a/arch/x86/core/ia32/intstub.S +++ b/arch/x86/core/ia32/intstub.S @@ -112,11 +112,12 @@ SECTION_FUNC(PINNED_TEXT, _interrupt_enter) * EAX = isr_param, EDX = isr */ - /* Push EDI as we will use it for scratch space. + /* Push EBP as we will use it for scratch space. + * Also it helps in stack unwinding * Rest of the callee-saved regs get saved by invocation of C * functions (isr handler, arch_swap(), etc) */ - pushl %edi + pushl %ebp /* load %ecx with &_kernel */ @@ -131,17 +132,17 @@ SECTION_FUNC(PINNED_TEXT, _interrupt_enter) jne alreadyOnIntStack /* - * switch to base of the interrupt stack: save esp in edi, then load + * switch to base of the interrupt stack: save esp in ebp, then load * irq_stack pointer */ - movl %esp, %edi + movl %esp, %ebp movl _kernel_offset_to_irq_stack(%ecx), %esp /* save thread's stack pointer onto base of interrupt stack */ - pushl %edi /* Save stack pointer */ + pushl %ebp /* Save stack pointer */ #ifdef CONFIG_PM cmpl $0, _kernel_offset_to_idle(%ecx) @@ -265,7 +266,7 @@ alreadyOnIntStack: #endif /* CONFIG_LAZY_FPU_SHARING */ /* Restore volatile registers and return to the interrupted thread */ - popl %edi + popl %ebp popl %ecx popl %edx popl %eax @@ -298,7 +299,7 @@ noReschedule: */ nestedInterrupt: - popl %edi + popl %ebp popl %ecx /* pop volatile registers in reverse order */ popl %edx popl %eax diff --git a/arch/x86/core/ia32/perf.c b/arch/x86/core/ia32/perf.c new file mode 100644 index 0000000000000..1f212317626fa --- /dev/null +++ b/arch/x86/core/ia32/perf.c @@ -0,0 +1,81 @@ +/* + * Copyright (c) 2023 KNS Group LLC (YADRO) + * Copyright (c) 2020 Yonatan Goldschmidt + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include + +static bool valid_stack(uintptr_t addr, k_tid_t current) +{ + return current->stack_info.start <= addr && + addr < current->stack_info.start + current->stack_info.size; +} + +/* interruption stack frame */ +struct isf { + uint32_t ebp; + uint32_t ecx; + uint32_t edx; + uint32_t eax; + uint32_t eip; +}; + +/* + * This function use frame pointers to unwind stack and get trace of return addresses. + * Return addresses are translated in corresponding function's names using .elf file. + * So we get function call trace + */ +size_t arch_perf_current_stack_trace(uintptr_t *buf, size_t size) +{ + if (size < 1U) + return 0; + + size_t idx = 0; + + const struct isf * const isf = + *((struct isf **)(((void **)_current_cpu->irq_stack)-1)); + /* + * In x86 (arch/x86/core/ia32/intstub.S) %eip and %ebp + * are saved at the beginning of _interrupt_enter in order, that described + * in struct esf. Core switch %esp to + * _current_cpu->irq_stack and push %esp on irq stack + * + * The following lines lines do the reverse things to get %eip and %ebp + * from thread stack + */ + void **fp = (void **)isf->ebp; + + /* + * %ebp is frame pointer. + * + * stack frame in memory: + * (addresses growth up) + * .... + * ra + * %ebp (next) <- %ebp (curr) + * .... + */ + + buf[idx++] = (uintptr_t)isf->eip; + while (valid_stack((uintptr_t)fp, _current)) { + if (idx >= size) + return 0; + + buf[idx++] = (uintptr_t)fp[1]; + void **new_fp = (void **)fp[0]; + + /* + * anti-infinity-loop if + * new_fp can't be smaller than fp, cause the stack is growing down + * and trace moves deeper into the stack + */ + if (new_fp <= fp) { + break; + } + fp = new_fp; + } + + return idx; +} From 6654609b0c8746a7ccf5a9c9d1c0577512641440 Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 15:06:58 +0300 Subject: [PATCH 5/7] scripts: profiling: Add stackcollapse script Samples, that were obtained by profiling perf tool, can be be translated into flamegraph using stackcollapse.py script. Originally-by: Yonatan Goldschmidt Signed-off-by: Mikhail Kushnerov --- scripts/profiling/stackcollapse.py | 65 ++++++++++++++++++++++++++++++ 1 file changed, 65 insertions(+) create mode 100644 scripts/profiling/stackcollapse.py diff --git a/scripts/profiling/stackcollapse.py b/scripts/profiling/stackcollapse.py new file mode 100644 index 0000000000000..38088527fcaf8 --- /dev/null +++ b/scripts/profiling/stackcollapse.py @@ -0,0 +1,65 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2023 KNS Group LLC (YADRO) +# Copyright (c) 2020 Yonatan Goldschmidt +# +# SPDX-License-Identifier: Apache-2.0 + +""" +Stack compressor for FlameGraph + +This translate stack samples captured by perf subsystem into format +used by flamegraph.pl. Translation uses .elf file to get function names +from addresses + +Usage: + ./script/perf/stackcollapse.py +""" + +import re +import sys +import struct +import binascii +from functools import lru_cache +from elftools.elf.elffile import ELFFile + + +@lru_cache(maxsize=None) +def addr_to_sym(addr, elf): + symtab = elf.get_section_by_name(".symtab") + for sym in symtab.iter_symbols(): + if sym.entry.st_info.type == "STT_FUNC" and sym.entry.st_value <= addr < sym.entry.st_value + sym.entry.st_size: + return sym.name + if addr == 0: + return "nullptr" + return "[unknown]" + + +def collapse(buf, elf): + while buf: + count, = struct.unpack_from(">Q", buf) + assert count > 0 + addrs = struct.unpack_from(f">{count}Q", buf, 8) + + func_trace = reversed(list(map(lambda a: addr_to_sym(a, elf), addrs))) + prev_func = next(func_trace) + line = prev_func + # merge dublicate functions + for func in func_trace: + if prev_func != func: + prev_func = func + line += ";" + func + + print(line, 1) + buf = buf[8 + 8 * count:] + + +if __name__ == "__main__": + elf = ELFFile(open(sys.argv[2], "rb")) + with open(sys.argv[1], "r") as f: + inp = f.read() + + lines = inp.splitlines() + assert int(re.match(r"Perf buf length (\d+)", lines[0]).group(1)) == len(lines) - 1 + buf = binascii.unhexlify("".join(lines[1:])) + collapse(buf, elf) From c8b2389ac0d6bbb3aaa1c6648cb259758feae1b1 Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 15:12:45 +0300 Subject: [PATCH 6/7] doc: profiling: Add doc for perf tool Add doc for profiling perf tool Signed-off-by: Mikhail Kushnerov --- doc/services/index.rst | 1 + doc/services/profiling/index.rst | 11 ++++ doc/services/profiling/perf.rst | 91 ++++++++++++++++++++++++++++++++ 3 files changed, 103 insertions(+) create mode 100644 doc/services/profiling/index.rst create mode 100644 doc/services/profiling/perf.rst diff --git a/doc/services/index.rst b/doc/services/index.rst index b8c0534e82dab..d900f110a65af 100644 --- a/doc/services/index.rst +++ b/doc/services/index.rst @@ -28,6 +28,7 @@ OS Services pm/index.rst portability/index.rst poweroff.rst + profiling/index.rst shell/index.rst serialization/index.rst settings/index.rst diff --git a/doc/services/profiling/index.rst b/doc/services/profiling/index.rst new file mode 100644 index 0000000000000..a6040a4509bbd --- /dev/null +++ b/doc/services/profiling/index.rst @@ -0,0 +1,11 @@ +.. _profiling: + +Profiling +######### + +Required Kconfig: :kconfig:option:`CONFIG_PROFILING` + +.. toctree:: + :maxdepth: 1 + + perf.rst diff --git a/doc/services/profiling/perf.rst b/doc/services/profiling/perf.rst new file mode 100644 index 0000000000000..9d421e88f1dc9 --- /dev/null +++ b/doc/services/profiling/perf.rst @@ -0,0 +1,91 @@ +.. _profiling-perf: + + +Perf +#### + + +Perf is a profiler tool, based on stack tracing. It can be used to light weight profiling +almost without any code overhead. + +Work principe +************* + +``perf record`` shell-command starts timer with perf tracer function. +Timers are driven by inerrupts, so perf tracer function is calling during interruption. +Zephyr core save return address and frame pointer in interrupt stack or ``callee_saved`` +struture before caling interrupt hundler. So perf trace function makes stack traces by +using return address and frame pointer. + +Then stackcollapse.py script convert return addresses in stack trace to function names +by elf file and print them in required for FlameGraph format. + +Configuration +************* + +Configure this module using the following options. + +* :kconfig:option:`CONFIG_PROFILING_PERF`: enable the module. This opion add + perf command in shell. + +* :kconfig:option:`CONFIG_PROFILING_PERF_BUFFER_SIZE`: sets size of perf buffer, + where samples are saved before printing. + +Usage +***** + +More specific example can be found in :zephyr:code-sample:`profiling-perf`. + +#. Build with perf enabled and run. + +#. Begin perf sampling by shell-command + + .. code-block:: text + + perf record + + This command will start timer with perf sampler for *period* in seconds and + with *frequency* in hertz. + + Wait for the completion message ``perf done!`` or ``perf buf override!`` + (if perf buffer size is smaller than required). + +#. Print made by perf samles in terminal by shell-command + + .. code-block:: text + + perf printbuf + + Output exaple: + + .. code-block:: text + + Perf buf length 1985 + 0000000000000004 + 0000000080004e58 + 00000000800071ca + 0000000080000964 + aaaaaaaaaaaaaaaa + 0000000000000002 + .... + 00000000800163e0 + + Copy gotten output in some file, for example *perf_buf*. + +#. Translate perf samples by stackcollapse script to format, required by FlameGraph + + .. code-block:: bash + + python zephyr/scripts/perf/stackcollapse.py perf_buf /zephyr/zephyr.elf > perf_buf.folded + + And turn into .svg FlameGraph (for example *graph.svg*) + + .. code-block:: bash + + ./FlameGraph/flamegraph.pl perf_buf.folded > graph.svg + + All this step can be done by one command + + .. code-block:: bash + + python zephyr/scripts/perf/stackcollapse.py perf_buf /zephyr/zephyr.elf | ./FlameGraph/flamegraph.pl > graph.svg From bc9b550a3f19a41e2ea14cd8107425c9ffebc0df Mon Sep 17 00:00:00 2001 From: Mikhail Kushnerov Date: Thu, 23 May 2024 15:14:26 +0300 Subject: [PATCH 7/7] samples: profiling: Add sample for perf tool The operation of perf tool can be checked using this sample. Signed-off-by: Mikhail Kushnerov --- samples/subsys/profiling/perf/CMakeLists.txt | 10 + samples/subsys/profiling/perf/README.rst | 69 +++ .../profiling/perf/images/graph_example.svg | 521 ++++++++++++++++++ samples/subsys/profiling/perf/prj.conf | 6 + .../subsys/profiling/perf/pytest/test_perf.py | 39 ++ samples/subsys/profiling/perf/sample.yaml | 18 + samples/subsys/profiling/perf/src/main.c | 55 ++ samples/subsys/profiling/profiling.rst | 10 + 8 files changed, 728 insertions(+) create mode 100644 samples/subsys/profiling/perf/CMakeLists.txt create mode 100644 samples/subsys/profiling/perf/README.rst create mode 100644 samples/subsys/profiling/perf/images/graph_example.svg create mode 100644 samples/subsys/profiling/perf/prj.conf create mode 100755 samples/subsys/profiling/perf/pytest/test_perf.py create mode 100644 samples/subsys/profiling/perf/sample.yaml create mode 100644 samples/subsys/profiling/perf/src/main.c create mode 100644 samples/subsys/profiling/profiling.rst diff --git a/samples/subsys/profiling/perf/CMakeLists.txt b/samples/subsys/profiling/perf/CMakeLists.txt new file mode 100644 index 0000000000000..f21d25038e1dc --- /dev/null +++ b/samples/subsys/profiling/perf/CMakeLists.txt @@ -0,0 +1,10 @@ +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.20.0) + +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(perf) + +target_sources(app PRIVATE src/main.c) diff --git a/samples/subsys/profiling/perf/README.rst b/samples/subsys/profiling/perf/README.rst new file mode 100644 index 0000000000000..124ee496615c3 --- /dev/null +++ b/samples/subsys/profiling/perf/README.rst @@ -0,0 +1,69 @@ +.. zephyr:code-sample:: profiling-perf + :name: Perf tool + + Send perf samples to the host with console support + +This application can be used to demonstrate :ref:`profiling-perf` work. + +Requirements +************ + +Perf tool so far implemente only for riscv and x86_64 architectures. + +Usage example +************* + +Build an image with: + +.. zephyr-app-commands:: + :zephyr-app: samples/subsys/profiling/perf + :board: qemu_riscv64 + :goals: build + :compact: + +After the sample starts, enter shell command: + +.. code-block:: console + + uart:~$ perf record + +Wait for the completion message ``perf done!`` or ``perf buf override!`` +(if perf buffer size is smaller than required). + +Print made by perf samles in terminal by shell-command: + +.. code-block:: console + + uart:~$ perf printbuf + +Output exaple: + +.. code-block:: console + + Perf buf length 2046 + 0000000000000004 + 00000000001056b2 + 0000000000108192 + 000000000010052f + 0000000000000000 + .... + 000000000010052f + 0000000000000000 + +Copy gotten output in some file, for example *perf_buf*. + +Make graph.svg with :zephyr_file:`scripts/perf/stackcollapse.py` and +`FlameGraph`_: + +.. _FlameGraph: https://github.com/brendangregg/FlameGraph/ + +.. code-block:: shell + + python scripts/perf/stackcollapse.py perf_buf build/zephyr/zephyr.elf | /flamegraph.pl > graph.svg + +Graph example +============= + +.. image:: images/graph_example.svg + :align: center + :alt: graph example diff --git a/samples/subsys/profiling/perf/images/graph_example.svg b/samples/subsys/profiling/perf/images/graph_example.svg new file mode 100644 index 0000000000000..19c2e8d1837ac --- /dev/null +++ b/samples/subsys/profiling/perf/images/graph_example.svg @@ -0,0 +1,521 @@ + + + + + + + + + + + + + + +Flame Graph + +Reset Zoom +Search +ic + + + +z_impl_k_busy_wait (60 samples, 23.26%) +z_impl_k_busy_wait + + +sys_clock_cycle_get_32 (40 samples, 15.50%) +sys_clock_cycle_get_32 + + +all (258 samples, 100%) + + + +sys_clock_cycle_get_32 (20 samples, 7.75%) +sys_clock_.. + + +sys_clock_cycle_get_32 (20 samples, 7.75%) +sys_clock_.. + + +z_impl_k_busy_wait (78 samples, 30.23%) +z_impl_k_busy_wait + + +sys_clock_cycle_get_32 (40 samples, 15.50%) +sys_clock_cycle_get_32 + + +z_impl_k_busy_wait (20 samples, 7.75%) +z_impl_k_b.. + + +func_0 (80 samples, 31.01%) +func_0 + + +sys_clock_cycle_get_32 (59 samples, 22.87%) +sys_clock_cycle_get_32 + + +z_impl_k_busy_wait (40 samples, 15.50%) +z_impl_k_busy_wait + + +main (218 samples, 84.50%) +main + + +func_0_1 (40 samples, 15.50%) +func_0_1 + + +idle (40 samples, 15.50%) +idle + + +func_1 (60 samples, 23.26%) +func_1 + + +arch_cpu_idle (40 samples, 15.50%) +arch_cpu_idle + + +z_thread_entry (258 samples, 100.00%) +z_thread_entry + + +bg_thread_main (218 samples, 84.50%) +bg_thread_main + + +func_0_0 (20 samples, 7.75%) +func_0_0 + + +z_impl_k_busy_wait (20 samples, 7.75%) +z_impl_k_b.. + + +func_2 (78 samples, 30.23%) +func_2 + + +[unknown] (258 samples, 100.00%) +[unknown] + + + diff --git a/samples/subsys/profiling/perf/prj.conf b/samples/subsys/profiling/perf/prj.conf new file mode 100644 index 0000000000000..e93083d3da327 --- /dev/null +++ b/samples/subsys/profiling/perf/prj.conf @@ -0,0 +1,6 @@ +CONFIG_PROFILING=y +CONFIG_PROFILING_PERF=y +CONFIG_THREAD_STACK_INFO=y +CONFIG_SMP=n +CONFIG_SHELL=y +CONFIG_FRAME_POINTER=y diff --git a/samples/subsys/profiling/perf/pytest/test_perf.py b/samples/subsys/profiling/perf/pytest/test_perf.py new file mode 100755 index 0000000000000..1bb4c6a7cb002 --- /dev/null +++ b/samples/subsys/profiling/perf/pytest/test_perf.py @@ -0,0 +1,39 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2023 KNS Group LLC (YADRO) +# +# SPDX-License-Identifier: Apache-2.0 + +import logging +import re + +from twister_harness import Shell +from twister_harness import DeviceAdapter + +logger = logging.getLogger(__name__) + + +def test_shell_perf(dut: DeviceAdapter, shell: Shell): + + shell.base_timeout=10 + + logger.info('send "perf record 200 99" command') + lines = shell.exec_command('perf record 200 99') + assert 'Enabled perf' in lines, 'expected response not found' + lines = dut.readlines_until(regex='.*Perf done!', print_output=True) + logger.info('response is valid') + + logger.info('send "perf printbuf" command') + lines = shell.exec_command('perf printbuf') + lines = lines[1:-1] + match = re.match(r"Perf buf length (\d+)", lines[0]) + assert match is not None, 'expected response not found' + length = int(match.group(1)) + lines = lines[1:] + assert length != 0, '0 length' + assert length == len(lines), 'length dose not match with count of lines' + + i = 0 + while i < length: + i += int(lines[i], 16) + 1 + assert i <= length, 'one of the samples is not true to size' diff --git a/samples/subsys/profiling/perf/sample.yaml b/samples/subsys/profiling/perf/sample.yaml new file mode 100644 index 0000000000000..261c2f957bb50 --- /dev/null +++ b/samples/subsys/profiling/perf/sample.yaml @@ -0,0 +1,18 @@ +sample: + description: Sample, that can be used for testing profiling perf tool + name: perf sample + +tests: + sample.perf: + tags: + - perf + - profiling + extra_configs: + - CONFIG_PROFILING_PERF_BUFFER_SIZE=128 + filter: CONFIG_RISCV or CONFIG_X86 + integration_platforms: + - qemu_riscv64 + - qemu_riscv32 + - qemu_x86_64 + - qemu_x86 + harness: pytest diff --git a/samples/subsys/profiling/perf/src/main.c b/samples/subsys/profiling/perf/src/main.c new file mode 100644 index 0000000000000..7576e1994ce0d --- /dev/null +++ b/samples/subsys/profiling/perf/src/main.c @@ -0,0 +1,55 @@ +/* + * Copyright (c) 2023 KNS Group LLC (YADRO) + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include + +#define WAIT_KOEF 10000 + +#define NOINLINE __attribute__((noinline)) + +int NOINLINE func_0_0(void) +{ + k_busy_wait(1*WAIT_KOEF); + return 0; +} + +int NOINLINE func_0_1(void) +{ + k_busy_wait(2*WAIT_KOEF); + return 0; +} + +int NOINLINE func_0(void) +{ + k_busy_wait(1*WAIT_KOEF); + func_0_0(); + func_0_1(); + return 0; +} + +int NOINLINE func_1(void) +{ + k_busy_wait(3*WAIT_KOEF); + return 0; +} + +int NOINLINE func_2(void) +{ + k_busy_wait(4*WAIT_KOEF); + return 0; +} + +int main(void) +{ + while (1) { + k_usleep(1000); + func_0(); + func_1(); + func_2(); + } + return 0; +} diff --git a/samples/subsys/profiling/profiling.rst b/samples/subsys/profiling/profiling.rst new file mode 100644 index 0000000000000..a9765517a4b39 --- /dev/null +++ b/samples/subsys/profiling/profiling.rst @@ -0,0 +1,10 @@ +.. _profiling-samples: + +Profiling subsystem samples +########################### + +.. toctree:: + :maxdepth: 1 + :glob: + + **/*