From 3e25d441a50f7f2263c3d1a355ee53770de5e6bf Mon Sep 17 00:00:00 2001 From: Darian Leung Date: Tue, 19 Feb 2019 03:04:17 +0800 Subject: [PATCH] freertos: Add real time stats example The following commit adds a real time stats example demonstrating how to obtain task CPU usage statistics over a period of time, as opposed to the current run time stats in FreeRTOS which measures task CPU usage as a percentage of total system run time. --- .../freertos/real_time_stats/CMakeLists.txt | 6 + .../system/freertos/real_time_stats/Makefile | 9 + .../system/freertos/real_time_stats/README.md | 71 +++++++ .../freertos/real_time_stats/example_test.py | 31 +++ .../real_time_stats/main/CMakeLists.txt | 4 + .../real_time_stats/main/component.mk | 5 + .../freertos/real_time_stats/main/main.c | 186 ++++++++++++++++++ .../real_time_stats/sdkconfig.defaults | 2 + 8 files changed, 314 insertions(+) create mode 100644 examples/system/freertos/real_time_stats/CMakeLists.txt create mode 100644 examples/system/freertos/real_time_stats/Makefile create mode 100644 examples/system/freertos/real_time_stats/README.md create mode 100644 examples/system/freertos/real_time_stats/example_test.py create mode 100644 examples/system/freertos/real_time_stats/main/CMakeLists.txt create mode 100644 examples/system/freertos/real_time_stats/main/component.mk create mode 100644 examples/system/freertos/real_time_stats/main/main.c create mode 100644 examples/system/freertos/real_time_stats/sdkconfig.defaults diff --git a/examples/system/freertos/real_time_stats/CMakeLists.txt b/examples/system/freertos/real_time_stats/CMakeLists.txt new file mode 100644 index 0000000000..ac37a61f3a --- /dev/null +++ b/examples/system/freertos/real_time_stats/CMakeLists.txt @@ -0,0 +1,6 @@ +# The following lines of boilerplate have to be in your project's CMakeLists +# in this exact order for cmake to work correctly +cmake_minimum_required(VERSION 3.5) + +include($ENV{IDF_PATH}/tools/cmake/project.cmake) +project(real_time_stats) diff --git a/examples/system/freertos/real_time_stats/Makefile b/examples/system/freertos/real_time_stats/Makefile new file mode 100644 index 0000000000..f99f584a31 --- /dev/null +++ b/examples/system/freertos/real_time_stats/Makefile @@ -0,0 +1,9 @@ +# +# This is a project Makefile. It is assumed the directory this Makefile resides in is a +# project subdirectory. +# + +PROJECT_NAME := real_time_stats + +include $(IDF_PATH)/make/project.mk + diff --git a/examples/system/freertos/real_time_stats/README.md b/examples/system/freertos/real_time_stats/README.md new file mode 100644 index 0000000000..1ee73a34f1 --- /dev/null +++ b/examples/system/freertos/real_time_stats/README.md @@ -0,0 +1,71 @@ +# FreeRTOS Real Time Stats Example + +(See the README.md file in the upper level 'examples' directory for more information about examples.) + +FreeRTOS provides the function `vTaskGetRunTimeStats()` to obtain CPU usage statistics of tasks. However, these statistics are with respect to the entire runtime of FreeRTOS (i.e. **run time stats**). Furthermore, statistics of `vTaskGetRunTimeStats()` are only valid whilst the timer for run time statistics has not overflowed. + +This example demonstrates how to get CPU usage statistics of tasks with respect to a specified duration (i.e. **real time stats**) rather than over the entire runtime of FreeRTOS. The `print_real_time_stats()` function of this example demonstrates how this can be achieved. + +## How to use example + +### Hardware Required + +This example should be able to run on any commonly available ESP32 development board. + +### Configure the project + +``` +make menuconfig +``` + +* Set serial port under Serial Flasher Options. + +* Enable FreeRTOS to collect run time stats under `Component Config->FreeRTOS` + +* The clock source of reference timer used for FreeRTOS statistics can be configured under `Component Config->FreeRTOS` + +### Build and Flash + +Build the project and flash it to the board, then run monitor tool to view serial output: + +``` +make -j4 flash monitor +``` + +(To exit the serial monitor, type ``Ctrl-]``.) + +See the Getting Started Guide for full steps to configure and use ESP-IDF to build projects. + +## Example Output + +``` +Getting real time stats over 100 ticks +| Task | Run Time | Percentage +| stats | 1304 | 0% +| IDLE0 | 206251 | 10% +| IDLE1 | 464785 | 23% +| spin2 | 225389 | 11% +| spin0 | 227174 | 11% +| spin4 | 225303 | 11% +| spin1 | 207264 | 10% +| spin3 | 225331 | 11% +| spin5 | 225369 | 11% +| Tmr Svc | 0 | 0% +| esp_timer | 0 | 0% +| ipc1 | 0 | 0% +| ipc0 | 0 | 0% +Real time stats obtained +``` + +- When compiled in dual core mode, the percentage is with respect to the combined run time of both CPUs. Thus, `50%` would indicate full utilization of a single CPU. +- In single core mode, the percentage is with respect to a single CPU. Thus, `100%` would indicate full utilization of the CPU. + +The unit of `Run Time` is the period of the timer clock source used for FreeRTOS statistics. + +## Troubleshooting + +``` +Getting real time stats over 100 ticks +Error getting real time stats +``` +If the above is output when running the example, users should check the return value of `print_real_time_stats()` to determine the reason for failure. diff --git a/examples/system/freertos/real_time_stats/example_test.py b/examples/system/freertos/real_time_stats/example_test.py new file mode 100644 index 0000000000..f5ae64c3e4 --- /dev/null +++ b/examples/system/freertos/real_time_stats/example_test.py @@ -0,0 +1,31 @@ +from __future__ import print_function +import os +import sys + +try: + import IDF +except ImportError: + # this is a test case write with tiny-test-fw. + # to run test cases outside tiny-test-fw, + # we need to set environment variable `TEST_FW_PATH`, + # then get and insert `TEST_FW_PATH` to sys path before import FW module + test_fw_path = os.getenv('TEST_FW_PATH') + if test_fw_path and test_fw_path not in sys.path: + sys.path.insert(0, test_fw_path) + import IDF + +STATS_TASK_ITERS = 3 +STATS_TASK_EXPECT = "Real time stats obtained" + + +@IDF.idf_example_test(env_tag='Example_WIFI') +def test_real_time_stats_example(env, extra_data): + dut = env.get_dut('real_time_stats', 'examples/system/freertos/real_time_stats') + dut.start_app() + + for iteration in range(0, STATS_TASK_ITERS): + dut.expect(STATS_TASK_EXPECT) + + +if __name__ == '__main__': + test_real_time_stats_example() diff --git a/examples/system/freertos/real_time_stats/main/CMakeLists.txt b/examples/system/freertos/real_time_stats/main/CMakeLists.txt new file mode 100644 index 0000000000..85970762ab --- /dev/null +++ b/examples/system/freertos/real_time_stats/main/CMakeLists.txt @@ -0,0 +1,4 @@ +set(COMPONENT_SRCS "main.c") +set(COMPONENT_ADD_INCLUDEDIRS ".") + +register_component() diff --git a/examples/system/freertos/real_time_stats/main/component.mk b/examples/system/freertos/real_time_stats/main/component.mk new file mode 100644 index 0000000000..0b9d7585e7 --- /dev/null +++ b/examples/system/freertos/real_time_stats/main/component.mk @@ -0,0 +1,5 @@ +# +# "main" pseudo-component makefile. +# +# (Uses default behaviour of compiling all source files in directory, adding 'include' to include path.) + diff --git a/examples/system/freertos/real_time_stats/main/main.c b/examples/system/freertos/real_time_stats/main/main.c new file mode 100644 index 0000000000..96a199bfec --- /dev/null +++ b/examples/system/freertos/real_time_stats/main/main.c @@ -0,0 +1,186 @@ +/* FreeRTOS Real Time Stats Example + + This example code is in the Public Domain (or CC0 licensed, at your option.) + + Unless required by applicable law or agreed to in writing, this + software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR + CONDITIONS OF ANY KIND, either express or implied. +*/ + +#include +#include +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" +#include "freertos/semphr.h" +#include "esp_err.h" + +#define NUM_OF_SPIN_TASKS 6 +#define SPIN_ITER 500000 //Actual CPU cycles used will depend on compiler optimization +#define SPIN_TASK_PRIO 2 +#define STATS_TASK_PRIO 3 +#define STATS_TICKS pdMS_TO_TICKS(1000) +#define ARRAY_SIZE_OFFSET 5 //Increase this if print_real_time_stats returns ESP_ERR_INVALID_SIZE + +static char task_names[NUM_OF_SPIN_TASKS][configMAX_TASK_NAME_LEN]; +static SemaphoreHandle_t sync_spin_task; +static SemaphoreHandle_t sync_stats_task; + +/** + * @brief Function to print the CPU usage of tasks over a given duration. + * + * This function will measure and print the CPU usage of tasks over a specified + * number of ticks (i.e. real time stats). This is implemented by simply calling + * uxTaskGetSystemState() twice separated by a delay, then calculating the + * differences of task run times before and after the delay. + * + * @note If any tasks are added or removed during the delay, the stats of + * those tasks will not be printed. + * @note This function should be called from a high priority task to minimize + * inaccuracies with delays. + * @note When running in dual core mode, each core will correspond to 50% of + * the run time. + * + * @param xTicksToWait Period of stats measurement + * + * @return + * - ESP_OK Success + * - ESP_ERR_NO_MEM Insufficient memory to allocated internal arrays + * - ESP_ERR_INVALID_SIZE Insufficient array size for uxTaskGetSystemState. Trying increasing ARRAY_SIZE_OFFSET + * - ESP_ERR_INVALID_STATE Delay duration too short + */ +static esp_err_t print_real_time_stats(TickType_t xTicksToWait) +{ + TaskStatus_t *start_array = NULL, *end_array = NULL; + UBaseType_t start_array_size, end_array_size; + uint32_t start_run_time, end_run_time; + esp_err_t ret; + + //Allocate array to store current task states + start_array_size = uxTaskGetNumberOfTasks() + ARRAY_SIZE_OFFSET; + start_array = malloc(sizeof(TaskStatus_t) * start_array_size); + if (start_array == NULL) { + ret = ESP_ERR_NO_MEM; + goto exit; + } + //Get current task states + start_array_size = uxTaskGetSystemState(start_array, start_array_size, &start_run_time); + if (start_array_size == 0) { + ret = ESP_ERR_INVALID_SIZE; + goto exit; + } + + vTaskDelay(xTicksToWait); + + //Allocate array to store tasks states post delay + end_array_size = uxTaskGetNumberOfTasks() + ARRAY_SIZE_OFFSET; + end_array = malloc(sizeof(TaskStatus_t) * end_array_size); + if (end_array == NULL) { + ret = ESP_ERR_NO_MEM; + goto exit; + } + //Get post delay task states + end_array_size = uxTaskGetSystemState(end_array, end_array_size, &end_run_time); + if (end_array_size == 0) { + ret = ESP_ERR_INVALID_SIZE; + goto exit; + } + + //Calculate total_elapsed_time in units of run time stats clock period. + uint32_t total_elapsed_time = (end_run_time - start_run_time); + if (total_elapsed_time == 0) { + ret = ESP_ERR_INVALID_STATE; + goto exit; + } + + printf("| Task | Run Time | Percentage\n"); + //Match each task in start_array to those in the end_array + for (int i = 0; i < start_array_size; i++) { + int k = -1; + for (int j = 0; j < end_array_size; j++) { + if (start_array[i].xHandle == end_array[j].xHandle) { + k = j; + //Mark that task have been matched by overwriting their handles + start_array[i].xHandle = NULL; + end_array[j].xHandle = NULL; + break; + } + } + //Check if matching task found + if (k >= 0) { + uint32_t task_elapsed_time = end_array[k].ulRunTimeCounter - start_array[i].ulRunTimeCounter; + uint32_t percentage_time = (task_elapsed_time * 100UL) / (total_elapsed_time * portNUM_PROCESSORS); + printf("| %s | %d | %d%%\n", start_array[i].pcTaskName, task_elapsed_time, percentage_time); + } + } + + //Print unmatched tasks + for (int i = 0; i < start_array_size; i++) { + if (start_array[i].xHandle != NULL) { + printf("| %s | Deleted\n", start_array[i].pcTaskName); + } + } + for (int i = 0; i < end_array_size; i++) { + if (end_array[i].xHandle != NULL) { + printf("| %s | Created\n", end_array[i].pcTaskName); + } + } + ret = ESP_OK; + +exit: //Common return path + free(start_array); + free(end_array); + return ret; +} + +static void spin_task(void *arg) +{ + xSemaphoreTake(sync_spin_task, portMAX_DELAY); + while (1) { + //Consume CPU cycles + for (int i = 0; i < SPIN_ITER; i++) { + __asm__ __volatile__("NOP"); + } + vTaskDelay(pdMS_TO_TICKS(100)); + } +} + +static void stats_task(void *arg) +{ + xSemaphoreTake(sync_stats_task, portMAX_DELAY); + + //Start all the spin tasks + for (int i = 0; i < NUM_OF_SPIN_TASKS; i++) { + xSemaphoreGive(sync_spin_task); + } + + //Print real time stats periodically + while (1) { + printf("\n\nGetting real time stats over %d ticks\n", STATS_TICKS); + if (print_real_time_stats(STATS_TICKS) == ESP_OK) { + printf("Real time stats obtained\n"); + } else { + printf("Error getting real time stats\n"); + } + vTaskDelay(pdMS_TO_TICKS(1000)); + } +} + +void app_main() +{ + //Allow other core to finish initialization + vTaskDelay(pdMS_TO_TICKS(100)); + + //Create semaphores to synchronize + sync_spin_task = xSemaphoreCreateCounting(NUM_OF_SPIN_TASKS, 0); + sync_stats_task = xSemaphoreCreateBinary(); + + //Create spin tasks + for (int i = 0; i < NUM_OF_SPIN_TASKS; i++) { + snprintf(task_names[i], configMAX_TASK_NAME_LEN, "spin%d", i); + xTaskCreatePinnedToCore(spin_task, task_names[i], 1024, NULL, SPIN_TASK_PRIO, NULL, tskNO_AFFINITY); + } + + //Create and start stats task + xTaskCreatePinnedToCore(stats_task, "stats", 4096, NULL, STATS_TASK_PRIO, NULL, tskNO_AFFINITY); + xSemaphoreGive(sync_stats_task); +} diff --git a/examples/system/freertos/real_time_stats/sdkconfig.defaults b/examples/system/freertos/real_time_stats/sdkconfig.defaults new file mode 100644 index 0000000000..184ea3b546 --- /dev/null +++ b/examples/system/freertos/real_time_stats/sdkconfig.defaults @@ -0,0 +1,2 @@ +CONFIG_FREERTOS_USE_TRACE_FACILITY=y +CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y \ No newline at end of file