diff --git a/sdk/bare/common/sys/prof_timer.c b/sdk/bare/common/sys/prof_timer.c new file mode 100644 index 00000000..da37ced7 --- /dev/null +++ b/sdk/bare/common/sys/prof_timer.c @@ -0,0 +1,137 @@ +#include "sys/prof_timer.h" +#include "drv/fpga_timer.h" +#include "sys/statistics.h" +#include "sys/util.h" +#include +#include +#include +#include + +static prof_timer_t *m_head = NULL; + +// Keep track of the number of registered items +// so that we can limit the number of loop iterations +static size_t m_num_registered = 0; + +void prof_timer_register(prof_timer_t *x) +{ + assert(x); + + prof_timer_t *entry = m_head; + size_t i = 0; + + // Find the end of the list. Since we track number of + // registrations we can limit our loop count in case of + // corruption in the linked list itself. + while (entry && entry->__next && (i < m_num_registered)) { + // If we are already registered don't double register. Just exit + if (entry == x) { + return; + } + + entry = entry->__next; + i++; + } + + if (entry) { + entry->__next = x; + } else { + // No registered entries + m_head = x; + } + + m_num_registered++; +} + +void prof_timer_unregister(prof_timer_t *x) +{ + assert(x); + + if (!m_head) { + return; + } + + // If we are the head then just remove the reference + // and make the next element in the list the head + if (x == m_head) { + m_head = m_head->__next; + x->__next = NULL; + m_num_registered--; + } else { + // Otherwise we will need to search for our reference by + // iterating over the list to find the element of the list + // that references us. Then we set the next reference of + // the previous element to our next reference. + prof_timer_t *prev = m_head; + size_t i = 0; + while (prev && (prev->__next) && (i < m_num_registered)) { + if (prev->__next == x) { + prev->__next = x->__next; + x->__next = NULL; + m_num_registered--; + break; + } + + i++; + } + } +} + +void __prof_timer_stop(prof_timer_t *x, uint32_t now_ticks) +{ + assert(x); + + if (x->is_enabled) { + double dt_usec = fpga_timer_ticks_to_usec(now_ticks - x->__start_time); + statistics_push(&(x->stats), dt_usec); + } +} + +void __prof_timer_stop_crit(prof_timer_t *x, uint32_t now_ticks) +{ + assert(x); + + __prof_timer_stop(x, now_ticks); + + if (x->is_enabled) { + util_critical_section_exit(x->__primask); + } +} + +void prof_timer_reset(prof_timer_t *x) +{ + assert(x); + + if (x->is_enabled) { + statistics_clear(&(x->stats)); + } +} + +size_t prof_timer_num_registered(void) +{ + return m_num_registered; +} + +bool prof_timer_iterate(prof_timer_t **current) +{ + assert(current); + + static size_t iteration = 0; + if (*current == NULL) { + *current = m_head; + iteration = 0; + } else { + *current = (*current)->__next; + iteration += 1; + } + + return (*current != NULL) && (iteration < m_num_registered); +} + +void prof_timer_reset_all(void) +{ + FOR_ALL_PROF_TIMERS(x) + { + prof_timer_reset(x); + } +} diff --git a/sdk/bare/common/sys/prof_timer.h b/sdk/bare/common/sys/prof_timer.h new file mode 100644 index 00000000..0324b5ff --- /dev/null +++ b/sdk/bare/common/sys/prof_timer.h @@ -0,0 +1,158 @@ +/** + * Timer for profiling specific sections of code. + * + * Can be used to register profiling timers for printouts later, or + * on it's own. This implements a linked list with a static head + * which can be iterated over to print out all statistics. This timer + * uses the sys/statistics module and the high precision + * drv/fpga_timer module at its core to provide high precision + * profiling statistics for how long a piece of code takes to run. + * + * Usage: + * + * @code + * // Some module.c + * + * prof_timer_t my_math_timer = { + * .name = "My Math", + * .is_enabled = true + * }; + * + * void module_init() { + * prof_timer_register(&my_math_timer); + * } + * + * void module_update() { + * // some code + * + * prof_timer_start(&my_math_timer); + * + * float x = sin(random()) * sqrt(PI); + * + * prof_timer_stop(&my_math_timer); + * + * // Some code + * } + * + * /////////////// + * + * // cmd_module.c + * + * ... + * // Print all profiling stats means + * FOR_ALL_PROF_TIMERS(t) { + * if (t->is_enabled) + * printf("%s %d", t->name, t->stats.mean); + * } + * + * /// OR + * + * prof_timer_t *t = NULL; + * while (prof_timer_iterate(&t)) { + * if (t->is_enabled) + * printf("%s %d", t->name, t->stats.mean); + * } + * + * ... + * @endcode + */ + +#ifndef PROF_TIMER_H +#define PROF_TIMER_H + +#include "drv/fpga_timer.h" +#include "sys/statistics.h" +#include "sys/util.h" + +#include +#include +#include + +// --------- +// Structure +// --------- + +typedef struct prof_timer { + // A name for printouts + const char *name; + + // Will the stats actually be calculated? + bool is_enabled; + + // Statistics for the timer. + statistics_t stats; + + // Private struct variables + uint32_t __start_time; + struct prof_timer *__next; + uint32_t __primask; +} prof_timer_t; + +// --------- +// Timer API +// --------- + +// Start the timer +static inline void prof_timer_start(prof_timer_t *x) +{ + x->__start_time = fpga_timer_now(); +} + +static inline void prof_timer_start_crit(prof_timer_t *x) +{ + if (x->is_enabled) { + x->__primask = util_critical_section_enter(); + } + + prof_timer_start(x); +} + +// Stop the timer and calculate the running statistics +void __prof_timer_stop(prof_timer_t *x, uint32_t now); +void __prof_timer_stop_crit(prof_timer_t *x, uint32_t now); + +// To remove as much function call and logical overhead as possible, +// measure now before __prof_timer_stop() is called. +#define prof_timer_stop(x) __prof_timer_stop(x, fpga_timer_now()) +#define prof_timer_stop_crit(x) __prof_timer_stop_crit(x, fpga_timer_now()) + +/** Reset the timer statistics. */ +void prof_timer_reset(prof_timer_t *x); + +// ------------------------------ +// Linked List / Registration API +// ------------------------------ + +// Register the Profiling Timer with the internal linked list +void prof_timer_register(prof_timer_t *x); + +// Unregister the Profiling Timer with the internal linked list +void prof_timer_unregister(prof_timer_t *x); + +// Get the number of registered profile timers. +size_t prof_timer_num_registered(void); + +// ------------- +// Iteration API +// ------------- + +/** + * Iterate through all registered timers: + * + * Usage: + * prof_timer_t *current = NULL; + * while (prof_timer_iterate(¤t)) { + * // DO stuff. + * } + */ +bool prof_timer_iterate(prof_timer_t **current); + +/** + * FOR_ALL_PROF_TIMERS implements a safe use case of prof_timer_iterate() which + * scopes `var` within it. This iterates through all elements in the Profiling Timer List. + */ +#define FOR_ALL_PROF_TIMERS(var) for (prof_timer_t *var = NULL; prof_timer_iterate(&var);) + +void prof_timer_reset_all(void); + +#endif // PROF_TIMER_H diff --git a/sdk/bare/common/sys/util.c b/sdk/bare/common/sys/util.c index d9ff16b3..1ab87432 100644 --- a/sdk/bare/common/sys/util.c +++ b/sdk/bare/common/sys/util.c @@ -1 +1,19 @@ #include "sys/util.h" +#include "xil_exception.h" +#include + +uint32_t util_critical_section_enter(void) +{ + // This Xilinx driver only disables the IRQ exceptions which is fine for us. + Xil_ExceptionDisable(); + + // Return a garbage primask... This isn't used by us! + return 0; +} + +void util_critical_section_exit(uint32_t primask) +{ + // TODO(NP): We are ignoring the mask!!! Just use the Xilinx driver + // to return to the "normal" exception state. + Xil_ExceptionEnable(); +} diff --git a/sdk/bare/common/sys/util.h b/sdk/bare/common/sys/util.h index 3de75ed6..d8bcd874 100644 --- a/sdk/bare/common/sys/util.h +++ b/sdk/bare/common/sys/util.h @@ -1,6 +1,8 @@ #ifndef UTIL_H #define UTIL_H +#include + #define MIN(x, y) (((x) > (y)) ? (y) : (x)) #define MAX(x, y) (((x) > (y)) ? (x) : (y)) @@ -8,4 +10,7 @@ #define STR_EQ(str1, str2) (strcmp(str1, str2) == 0) +uint32_t util_critical_section_enter(void); +void util_critical_section_exit(uint32_t primask); + #endif // UTIL_H diff --git a/sdk/bare/user/usr/blink/cmd/cmd_blink.c b/sdk/bare/user/usr/blink/cmd/cmd_blink.c index 79c89f03..c530638d 100644 --- a/sdk/bare/user/usr/blink/cmd/cmd_blink.c +++ b/sdk/bare/user/usr/blink/cmd/cmd_blink.c @@ -20,7 +20,8 @@ static command_help_t cmd_help[] = { { "deinit", "Stop task" }, { "stats print", "Print stats" }, { "stats reset", "Reset stats" }, - + { "expen run<1|2|3> ", "Run an expensive operation N times" }, + { "expen stats ", "Print stats for expensive operation" }, }; void cmd_blink_register(void) @@ -120,6 +121,52 @@ int cmd_blink(int argc, char **argv) } } + if (argc >= 2 && strcmp("expen", argv[1]) == 0) { + if (argc == 4 && strcmp("run1", argv[2]) == 0) { + int N = atoi(argv[3]); + + if (N < 0 || N > 1000) { + return CMD_INVALID_ARGUMENTS; + } + + task_blink_expensive_run1(N); + return SUCCESS; + } + + if (argc == 4 && strcmp("run2", argv[2]) == 0) { + int N = atoi(argv[3]); + + if (N < 0 || N > 1000) { + return CMD_INVALID_ARGUMENTS; + } + + task_blink_expensive_run2(N); + return SUCCESS; + } + + if (argc == 4 && strcmp("run3", argv[2]) == 0) { + int N = atoi(argv[3]); + + if (N < 0 || N > 1000) { + return CMD_INVALID_ARGUMENTS; + } + + task_blink_expensive_run3(N); + return SUCCESS; + } + + if (argc == 4 && strcmp("stats", argv[2]) == 0) { + int N = atoi(argv[3]); + + if (N < 1 || N > 3) { + return CMD_INVALID_ARGUMENTS; + } + + task_blink_expensive_stats(N); + return SUCCESS; + } + } + // At any point, if an error is detected in given input command, // simply return an error code (defined in sys/defines.h) // diff --git a/sdk/bare/user/usr/blink/task_blink.c b/sdk/bare/user/usr/blink/task_blink.c index 63f9d4ea..4c53a337 100644 --- a/sdk/bare/user/usr/blink/task_blink.c +++ b/sdk/bare/user/usr/blink/task_blink.c @@ -1,8 +1,12 @@ #ifdef APP_BLINK #include "usr/blink/task_blink.h" +#include "sys/debug.h" +#include "sys/prof_timer.h" #include "sys/scheduler.h" #include "usr/user_config.h" +#include "xil_io.h" +#include #include #if USER_CONFIG_HARDWARE_TARGET == 4 @@ -37,6 +41,10 @@ static led_color_t led_colors[NUM_LED_COLORS] = { // Scheduler TCB which holds task "context" static task_control_block_t tcb; +static prof_timer_t my_math_timer = { .name = "Blink Math", .is_enabled = true }; +static prof_timer_t my_AXI_timer = { .name = "Blink AXI", .is_enabled = true }; +static prof_timer_t my_ADD_timer = { .name = "Blink ADD", .is_enabled = true }; + void task_blink_init(void) { // Fill TCB with parameters @@ -44,6 +52,9 @@ void task_blink_init(void) // Register task with scheduler scheduler_tcb_register(&tcb); + + // Register profiling timer + prof_timer_register(&my_math_timer); } void task_blink_deinit(void) @@ -108,4 +119,65 @@ void task_blink_stats_reset(void) task_stats_reset(&tcb.stats); } +void task_blink_expensive_run1(int N) +{ + for (int i = 0; i < N; i++) { + prof_timer_start_crit(&my_math_timer); + + double volatile x; + x = sin(random()) * sqrt(random()); + x += 0.0; + + prof_timer_stop_crit(&my_math_timer); + } +} + +void task_blink_expensive_run2(int N) +{ + for (int i = 0; i < N; i++) { + prof_timer_start_crit(&my_AXI_timer); + + // Read from the analog driver, channel 0 + volatile uint32_t reg_value; + reg_value = Xil_In32(0x43C00000); + + prof_timer_stop_crit(&my_AXI_timer); + } +} + +void task_blink_expensive_run3(int N) +{ + register volatile uint32_t tmp = 0; + + for (int i = 0; i < N; i++) { + prof_timer_start_crit(&my_ADD_timer); + + tmp = tmp + 1; + + prof_timer_stop_crit(&my_ADD_timer); + } +} + +void task_blink_expensive_stats(int i) +{ + prof_timer_t *t = NULL; + + if (i == 1) { + t = &my_math_timer; + } else if (i == 2) { + t = &my_AXI_timer; + } else if (i == 3) { + t = &my_ADD_timer; + } + + debug_printf("Name:\t%s\r\n", t->name); + debug_printf("Max:\t%.3f usec\r\n", t->stats.max); + debug_printf("Min:\t%.3f usec\r\n", t->stats.min); + debug_printf("Mean:\t%.3f usec\r\n", t->stats.mean); + debug_printf("Var:\t%.3f usec\r\n", statistics_variance(&t->stats)); + debug_printf("Num:\t%d samples\r\n", t->stats.num_samples); + + prof_timer_reset(t); +} + #endif // APP_BLINK diff --git a/sdk/bare/user/usr/blink/task_blink.h b/sdk/bare/user/usr/blink/task_blink.h index 303c5943..62cec2df 100644 --- a/sdk/bare/user/usr/blink/task_blink.h +++ b/sdk/bare/user/usr/blink/task_blink.h @@ -29,4 +29,10 @@ void task_blink_stats_print(void); // Reset the statistics gathered by the scheduler void task_blink_stats_reset(void); +// TODO(NP): remove these, this is only for debugging profiler timing +void task_blink_expensive_run1(int N); +void task_blink_expensive_run2(int N); +void task_blink_expensive_run3(int N); +void task_blink_expensive_stats(int i); + #endif // TASK_BLINK_H