diff --git a/sys/Makefile.dep b/sys/Makefile.dep index 2f25f7a5d0..c5f1fb13a0 100644 --- a/sys/Makefile.dep +++ b/sys/Makefile.dep @@ -32,4 +32,8 @@ ifneq (,$(filter rtt_cmd,$(USEMODULE))) FEATURES_REQUIRED += periph_rtt endif +ifneq (,$(filter trace,$(USEMODULE))) + USEMODULE += xtimer +endif + include $(RIOTBASE)/sys/test_utils/Makefile.dep diff --git a/sys/include/trace.h b/sys/include/trace.h new file mode 100644 index 0000000000..ea396341e1 --- /dev/null +++ b/sys/include/trace.h @@ -0,0 +1,100 @@ +/* + * Copyright (C) 2020 Kaspar Schleiser + * Freie Universität Berlin + * Inria + * + * This file is subject to the terms and conditions of the GNU Lesser + * General Public License v2.1. See the file LICENSE in the top level + * directory for more details. + */ + +/** + * @ingroup sys + * @brief Trace program flows + * + * This module allows recording program flow traces. It is meant for debugging + * in multi-threaded applications or when ISR's are involved. + * + * The `trace()` function takes an arbitrary (user chosen) uint32 value. + * Calling the function is safe from anywhere (user code, ISR, ...) and safely + * logs the function call time and user value in a trace buffer. + * + * At any point, `trace_dump()` can be used to print the trace buffer. + * + * The buffer has a default size of 512 entries, which can be overridden by + * defining CONFIG_TRACE_BUFSIZE. It can be cleared using `trace_reset()`. + * The trace buffer works like a ring-buffer. If it is full, it will start + * overwriting from the beginning. + * + * Tracing is made thread safe by disabling interrupts for critical sections. + * + * It does incur some overhead (at least a function call, getting the current + * time, a pair of enable/disable interrupts and a couple of memory accesses). + * + * Example: + * + * ~~~~~~~~~~~~~~~~~~~~~~~~ {.c} + * #include "trace.h" + * ... + * trace( + * + */ + +#ifndef TRACE_H +#define TRACE_H + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Add entry to trace buffer + * + * Adds the current time (e.g., xtimer_now_usec()) and @p val to the trace + * buffer. + * + * The value parameter is not used by the trace module itself. The caller is + * supposed to provide a meaningful value. + * It could be e.g., `0` at the beginning of a task and `1`at the end. + * + * @param[in] val user defined value + */ +void trace(uint32_t val); + +/** + * @brief Print the current trace buffer + * + * Will print the number of the trace log entry, the timestamp (first entry) or + * relative time since last entry, and the value supplied to the `trace()` call + * of each entry. + * + * Example output (after adding two traces, 3us apart, with values 0 and 1): + * + * n= 0 t= 1815312 v=0x00000000 + * n= 1 t=+ 3 v=0x00000001 + */ +void trace_dump(void); + +/** + * @brief Empty the trace buffer + */ +void trace_reset(void); + +#ifdef __cplusplus +} +#endif + +#endif /* TRACE_H */ +/** @} */ diff --git a/sys/trace/Makefile b/sys/trace/Makefile new file mode 100644 index 0000000000..48422e909a --- /dev/null +++ b/sys/trace/Makefile @@ -0,0 +1 @@ +include $(RIOTBASE)/Makefile.base diff --git a/sys/trace/trace.c b/sys/trace/trace.c new file mode 100644 index 0000000000..e898fb23eb --- /dev/null +++ b/sys/trace/trace.c @@ -0,0 +1,70 @@ +/* + * Copyright (C) 2020 Kaspar Schleiser + * Freie Universität Berlin + * Inria + * + * This file is subject to the terms and conditions of the GNU Lesser + * General Public License v2.1. See the file LICENSE in the top level + * directory for more details. + */ + +/** + * @ingroup sys + * @{ + * + * @file + * @brief Execution tracing module implementation + * + * @author Kaspar Schleiser + * + * @} + */ + +#include + +#include "irq.h" +#include "xtimer.h" + +#ifndef CONFIG_TRACE_BUFSIZE +#define CONFIG_TRACE_BUFSIZE 512 +#endif + +typedef struct { + uint32_t time; + uint32_t val; +} tracebuf_entry_t; + +static tracebuf_entry_t tracebuf[CONFIG_TRACE_BUFSIZE]; +static size_t tracebuf_pos; + +void trace(uint32_t val) +{ + unsigned state = irq_disable(); + + tracebuf[tracebuf_pos % CONFIG_TRACE_BUFSIZE] = + (tracebuf_entry_t){ .time = xtimer_now_usec(), .val = val }; + tracebuf_pos++; + irq_restore(state); +} + +void trace_dump(void) +{ + size_t n = tracebuf_pos > + CONFIG_TRACE_BUFSIZE ? CONFIG_TRACE_BUFSIZE : tracebuf_pos; + uint32_t t_last = 0; + + for (size_t i = 0; i < n; i++) { + printf("n=%4lu t=%s%8" PRIu32 " v=0x%08lx\n", (unsigned long)i, + i ? "+" : " ", + tracebuf[i].time - t_last, (unsigned long)tracebuf[i].val); + t_last = tracebuf[i].time; + } +} + +void trace_reset(void) +{ + unsigned state = irq_disable(); + + tracebuf_pos = 0; + irq_restore(state); +}