FreeRTOS Trace Macros Usage

Kernel
1

Hello, everyone! I have a problem with the trace macros. The goal is to be able to record the logs when the tasks are switched or created/deleted, and then visualise it in chrome://tracing. The idea was to define the macros in FreeRTOSConfig.h in the following manner:

#define traceTASK_SWITCHED_IN() printf("Task switched in: %s\n", pcTaskGetName(xTaskGetCurrentTaskHandle()))

#define traceTASK_CREATE( pxNewTCB ) printf("Task created: %s\n", pcTaskGetName((TaskHandle_t)pxNewTCB))

#define traceTASK_DELETE( pxTCB ) printf("Task deleted: %s\n", pcTaskGetName((TaskHandle_t)pxTCB))

#define traceTASK_SWITCHED_OUT() printf("Task switched out: %s\n", pcTaskGetName(xTaskGetCurrentTaskHandle()))

The main code looks as follows:

int main() {
    stdio_init_all();

    while (!stdio_usb_connected()) {
        sleep_ms(100);
    }

    printf("Menu:\ns -> start the code\n");

    int input_char = getchar();

    if (input_char == 's')
    {
        gpio_init(PICO_DEFAULT_LED_PIN);
        gpio_set_dir(PICO_DEFAULT_LED_PIN, GPIO_OUT);

        TaskHandle_t task1Handle = NULL;
        TaskHandle_t task2Handle = NULL;

        BaseType_t task1Result = xTaskCreate(vBlinkTask1, "Blink Task 1", 4096, NULL, 2, &task1Handle);
        vTaskDelay(pdMS_TO_TICKS(10));  // Allow time for printf to flush

        BaseType_t task2Result = xTaskCreate(vBlinkTask2, "Blink Task 2", 4096, NULL, 1, &task2Handle);  // Lower priority for fair scheduling
        vTaskDelay(pdMS_TO_TICKS(10));  // Allow time for printf to flush

        if (task1Result == pdPASS) {
            printf("Task 1 successfully created.\n");
        } else {
            printf("Failed to create Task 1.\n");
        }

        if (task2Result == pdPASS) {
            printf("Task 2 successfully created.\n");
        } else {
            printf("Failed to create Task 2.\n");
        }

        vTaskStartScheduler();
    }

    return 0;
}

Now coming to the problem… Weirdly, I only get the following log in my serial terminal:

Menu:
s -> start the code
Task created: Blink Task 1

I do not get any further messages about the creation of Blink Task 2 or any task switches. Has anyone seen that weird behavior before? Is the problem related to the slow printf function?

Thanks in advance!

2

Tasks switch in and out very rapidly and very quickly. Printing a string takes a comparatively long time (maybe 1000000x the time, depending), takes a huge amount of stack, and is normally not thread safe. Hence, you can’t define the switch in and switch out macros to print a string. If you want to visualise the behaviour then use something like Tracealyzer with logs to a RAM buffer (quick), or if your hardware is capable of toggling IO pins very quickly then use the macros to do that and view the pattern on an oscilloscope.

2 Likes
3

Thank you, Richard! Timing seems to be indeed a problem. I managed to implement it in a slightly different way, but the timing is still an issue I think. What I did is I created a function that saves log strings in a char buffer and after a pre-defined time, prints it all to the serial terminal.

Here is the function:

`void logTrace(const char *format, …)
{

//xLogMutex = xSemaphoreCreateMutex();
if (xLogMutex == NULL) {
    printf("Mutex not initialized!\n");
    return;
}


if (logIndex < MAX_LOGS) {
    char formattedMessage[MAX_LOG_LENGTH];  
    va_list args;

    va_start(args, format);
    vsnprintf(formattedMessage, MAX_LOG_LENGTH, format, args);  
    va_end(args);

    // Take the mutex before writing to the log array

    if (strstr(formattedMessage, "Blink") != NULL)
    {   
        if (xSemaphoreTake(xLogMutex, portMAX_DELAY) == pdTRUE)
        {
            strncpy(logArray[logIndex], formattedMessage, MAX_LOG_LENGTH);
            logIndex++;  // Increment the log index 
            xSemaphoreGive(xLogMutex);  // Release the mutex
        }
    }

    
} else {
    printf("Log array is full!\n");
}

}

void initLogging() {
// Create the mutex only once during initialization
xLogMutex = xSemaphoreCreateMutex();

if (xLogMutex == NULL) {
    printf("Failed to create log mutex!\n");
}

}`

Here is the way I use it in trace macros:

`#define traceTASK_SWITCHED_IN() logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName(pxCurrentTCB), “task”, “B”, 1, pcTaskGetName(pxCurrentTCB), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

#define traceTASK_SWITCHED_OUT() logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName(pxCurrentTCB), “task”, “E”, 1, pcTaskGetName(pxCurrentTCB), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

#define traceTASK_CREATE( pxNewTCB ) logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName((TaskHandle_t)pxNewTCB), “task”, “M”, 1, pcTaskGetName((TaskHandle_t)pxNewTCB), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

#define traceTASK_DELETE( pxTCB ) logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName((TaskHandle_t)pxTCB), “task”, “E”, 1, pcTaskGetName((TaskHandle_t)pxTCB), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

#define traceTASK_SUSPEND( pxTCB ) logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName((TaskHandle_t)pxTCB), “task”, “E”, 1, pcTaskGetName((TaskHandle_t)pxTCB), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

#define traceTASK_RESUME(xTask) logTrace(“{ "name": "%s", "cat": "%s", "ph": "%s","pid": %d, "tid": "%s", "ts": %lu },”,
pcTaskGetName((TaskHandle_t)xTask), “task”, “B”, 1, pcTaskGetName((TaskHandle_t)xTask), (unsigned long)(xTaskGetTickCount() * portTICK_PERIOD_MS * 1000))

`
This is the way, log looks like:
[
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “M”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 0 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “M”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 0 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 0 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 0 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 0 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 0 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 100000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 100000 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 200000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 200000 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 200000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 200000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 300000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 300000 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 400000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “B”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 400000 },
{ “name”: “Blink Task 1”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 1”, “ts”: 400000 },
{ “name”: “Blink Task 2”, “cat”: “task”, “ph”: “E”,“pid”: 1, “tid”: “Blink Task 2”, “ts”: 400000 },

But the result is the following:

image
image864Ă—152 11.8 KB

4

Generating formatted strings is also time consuming and will create timing issues as you are probably seeing. One possible solution is to encode the information you want to send out of the device in minimal possible space - like in different bits of uint32_t and then do the expansion on the PC.