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.

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)

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
+

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.

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()

examples/system/freertos/real_time_stats/main/CMakeLists.txt

@@ -0,0 +1,4 @@
+set(COMPONENT_SRCS "main.c")
+set(COMPONENT_ADD_INCLUDEDIRS ".")
+
+register_component()

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.)
+

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 <stdio.h>
+#include <stdlib.h>
+#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);
+}

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