How to properly use the user-defined tracing API?

[alexpaschoaletto]

EDIT: more comprehensive testing has been carried out with more targets.
Check the comments below for updates.

Original problem

Hey everyone! Hope you're all doing great.

Let's say I have a very basic project as given below (one can just paste it and run to see in action). We have two threads, the main and the log. The first simply prints "hello" every second and the other simply prints log events, waiting for incoming events on a message queue:

#include <zephyr/kernel.h>
#include <string.h>

enum evt {
    SWITCH_TO,
    SWITCH_AWAY,
};

typedef struct {
    enum evt event;
    uint32_t timestamp;
} log_t;

K_MSGQ_DEFINE(log_queue, sizeof(log_t), 10, 1);

void thread_function(void *a1, void *a2, void *a3){                 // main thread: prints "hello" every second
    for(;;){
        printk("hello\n");
        k_sleep(K_SECONDS(1));
    }
}


static void log_thread_function(void *a1, void *a2, void *a3){      // log thread: prints trace events
    log_t message;
    char event[10];
    for(;;){
        k_msgq_get(&log_queue, &message, K_FOREVER);                // blocks until an event is received
        switch(message.event){
            case SWITCH_TO:
                strcpy(event,"SWT_TO");
            break;
            case SWITCH_AWAY:
                strcpy(event,"SWT_AY");                            
            break;
            default:
                strcpy(event,"UK_EVT");
        }
        printk("[%u]\t%s\n", message.timestamp, event);
    }
};


K_THREAD_DEFINE(
    log_thread, 1024, log_thread_function,
    NULL, NULL, NULL, 10, 0, 0
);

K_THREAD_DEFINE(
    main_thread, 1024, thread_function,
    NULL, NULL, NULL, 5, 0, 0
);

Now what I want is that every time the main thread enters/leaves the CPU for execution, the SWITCH_TO and SWITCH_AWAY events are fired, respectively. And this is what I came up for the tracing, based on the provided sample code:

void trace(enum evt event){                                         // pushes a trace event to the log queue
    log_t message = {
        .event = event,
        .timestamp = k_cycle_get_32()
    };
    k_msgq_put(&log_queue, &message, K_NO_WAIT);
};

void sys_trace_thread_switched_in_user(){
    unsigned int key = irq_lock();
    k_tid_t thread = k_sched_current_thread_query();
    irq_unlock(key);
    if(thread != main_thread) return;
    trace(SWITCH_TO);
}

void sys_trace_thread_switched_out_user(){
    unsigned int key = irq_lock();
    k_tid_t thread = k_sched_current_thread_query();
    irq_unlock(key);
    if(thread != main_thread) return;
    trace(SWITCH_AWAY);
}

The whole point of my question is that although this implementation seems correct to my unexperienced Zephyr developer eyes, the actual log output features way more SWITCH_AWAY events than SWITCH_TO events, when in fact I was expecting more of a balanced outcome really:

I presume possible comments might warn me my method of checking for the thread is wrong, but just removing it doesn't really solve the issue. In fact, for these tracing functions:

void sys_trace_thread_switched_in_user(){
    trace(SWITCH_TO);
}

void sys_trace_thread_switched_out_user(){
    trace(SWITCH_AWAY);
}

The output still showcases a mismatch of SWITCH_TO and SWITCH_AWAY events:

So the obvious question is: Is this a bug I should report or is it just me not really getting what are these functions made for?
If the latter holds, what should I do instead to enable the proper function tracing?

Thank you all very much and sorry for the long message, I tried to keep it as simple and clear as possible.

[alexpaschoaletto]

Updates

Ever since the original post I made some kernel investigation and a few tweaks on the base example, making it even simpler. Just one application thread is necessary now, with the LOG_INF being used for logging instead:

#include <zephyr/logging/log.h>
#include <zephyr/kernel.h>
#include <string.h>

LOG_MODULE_REGISTER(tracing);

static void thread_function(void *a1, void *a2, void *a3){                 // main thread: prints "hello" every second
    for(;;){
        printf("\n%s\n\n", CONFIG_BOARD_TARGET);
        k_sleep(K_SECONDS(1));
    }
}

K_THREAD_DEFINE(
    main_thread, 1024, thread_function,
    NULL, NULL, NULL, 5, 0, 0
);


void sys_trace_thread_switched_in_user(){
    if(k_sched_current_thread_query() == main_thread) LOG_INF("SWT_TO");
}


void sys_trace_thread_switched_out_user(){
    if(k_sched_current_thread_query() == main_thread) LOG_INF("SWT_AY");
}

Alternatively it's possible to use the following functions, which will yield similar results while keeping the safeguards of the sample code:

void sys_trace_thread_switched_in_user(){
    unsigned int key = irq_lock();
    k_tid_t thread = k_sched_current_thread_query();
    if(thread == main_thread) LOG_INF("SWT_TO");
    irq_unlock(key);
}


void sys_trace_thread_switched_out_user(){
    unsigned int key = irq_lock();
    k_tid_t thread = k_sched_current_thread_query();
    if(thread == main_thread) LOG_INF("SWT_AY");
    irq_unlock(key);
}

Results

The following targets were tested:

• xiao_esp32c3: not working. at all. way too many SWT_AY's for each SWT_TO.
• esp32_wrover: not working, shows only the SWT_AY event.
• rpi_pico: working fine.
• qemu_riscv32: working fine.
• qemu_cortex_a53: working fine.
• qemu_xtensa: not working, output is the same as the esp32_wrover.
• qemu_malta: not working, output only shows SWT_TO events.

Output

The actual output observed for each target can be seen below.

target: xiao_esp32c3 (what you see in this specific case is supposed to be one single cycle, so only one SWT_TO and one SWT_AY):

target: esp32_wrover (doesn't even show the SWT_TO logs):

target: rpi_pico (works fine from what I can see):

target: qemu_riscv32:

target qemu_cortex_a53:

target qemu_xtensa (same problem as esp32):

target qemu_malta (opposite problem compared to the xtensa targets):