Merge pull request #14205 from kaspar030/add_trace_module

sys/trace: add trace module

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

sys/include/trace.h

@@ -0,0 +1,100 @@
+/*
+ * Copyright (C) 2020 Kaspar Schleiser <kaspar@schleiser.de>
+ *                    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(<user chosen uint32 value);
+ *
+ * trace_dump();
+ * ~~~~~~~~~~~~~~~~~~~~~~~~
+ *
+ * @{
+ *
+ * @brief       Execution tracing module API
+ *
+ * @file
+ * @author      Kaspar Schleiser <kaspar@schleiser.de>
+ *
+ */
+
+#ifndef TRACE_H
+#define TRACE_H
+
+#include <stdint.h>
+
+#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 */
+/** @} */

sys/trace/Makefile

@@ -0,0 +1 @@
+include $(RIOTBASE)/Makefile.base

sys/trace/trace.c

@@ -0,0 +1,70 @@
+/*
+ * Copyright (C) 2020 Kaspar Schleiser <kaspar@schleiser.de>
+ *                    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 <kaspar@schleiser.de>
+ *
+ * @}
+ */
+
+#include <stdio.h>
+
+#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);
+}

tests/trace/Makefile

@@ -0,0 +1,5 @@
+include ../Makefile.tests_common
+
+USEMODULE += trace
+
+include $(RIOTBASE)/Makefile.include

tests/trace/Makefile.ci

@@ -0,0 +1,13 @@
+BOARD_INSUFFICIENT_MEMORY := \
+    arduino-duemilanove \
+    arduino-leonardo \
+    arduino-nano \
+    arduino-uno \
+    atmega328p \
+    chronos \
+    msb-430 \
+    msb-430h \
+    nucleo-f031k6 \
+    nucleo-f042k6 \
+    stm32f030f4-demo \
+    #

tests/trace/main.c

@@ -0,0 +1,35 @@
+/*
+ * Copyright (C) 2020 Kaspar Schleiser <kaspar@schleiser.de>
+ *                    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     tests
+ * @{
+ *
+ * @file
+ * @brief       trace module test application
+ *
+ * This test application tests basic functionality of `sys/trace`.
+ *
+ * @author      Kaspar Schleiser <kaspar@schleiser.de>
+ *
+ * @}
+ */
+
+#include "trace.h"
+
+int main(void)
+{
+    trace(0);
+    trace(1);
+
+    trace_dump();
+
+    return 0;
+}

tests/trace/tests/01-run.py

@@ -0,0 +1,13 @@
+#!/usr/bin/env python3
+
+import sys
+from testrunner import run
+
+
+def testfunc(child):
+    child.expect("n=   0 t=\ +\d+ v=0x00000000\r\n")
+    child.expect("n=   1 t=\+\ +\d+ v=0x00000001\r\n")
+
+
+if __name__ == "__main__":
+    sys.exit(run(testfunc))