Custom Tracing Implementation

[timl2415]

Hi, we are working on an application that makes heavy use of work queues. We'd like some way to monitor work queue events to optimize timings/priorities etc. I was looking into user tracing configurable via:
https://docs.zephyrproject.org/latest/services/tracing/index.html

However, the user tracing interface seems pretty lacking in general, only thread tracing APIs seem user-definable while all other APIs are effectively no-opped. The user tracing sample only shows how to define these thread tracing APIs. This page https://developer.nordicsemi.com/nRF_Connect_SDK/doc/1.4.99-dev1/zephyr/guides/tracing/index.html seems to hint at some way for applications to redefine tracing macros but no examples exist. Is there a way to accomplish this without patching the SDK?

Thanks,

Tim

[timl2415]

In addition to the above it seems like there's no tracing around the actual handling of work items in the work queue, only around the APIs that feed into the work queue externally (k_work_submit, k_work_cancel etc.). So even with a fully implemented tracing backend it would be difficult to see which work items are getting processed.

[Susheel Nuguru]

I have not tried to for sometime but to achieve detailed tracing on work queues in the nrf5340 application using Zephyr, there are some ways to extend the current limited tracing capabilities in the Zephyr RTOS and Nordic SDK without needing to directly patch the SDK.

Try to redefine the tracing macros, 

The documentation suggests applications can redefine tracing macros, though examples are sparse. By creating custom definitions for work queue functions (such as k_work_submit and k_work_handler), you can add logging hooks and trace events. Define custom tracing macros like this in your application:

#define sys_trace_k_work_submit(work) custom_trace_k_work_submit(work)
#define sys_trace_k_work_handler_entry(work) custom_trace_k_work_handler_entry(work)
#define sys_trace_k_work_handler_exit(work) custom_trace_k_work_handler_exit(work)

Then, implement custom_trace_k_work_submit, custom_trace_k_work_handler_entry, and custom_trace_k_work_handler_exit functions to add logging, timestamps, or even direct telemetry outputs. This approach lets you track when work items are submitted and handled without modifying the SDK source. Then, implement custom_trace_k_work_submit, custom_trace_k_work_handler_entry, and custom_trace_k_work_handler_exit functions to add logging, timestamps, or even direct telemetry outputs. This approach lets you track when work items are submitted and handled without modifying the SDK source.

You can, use the  CONFIG_TRACING_USER macro can be configured to enable user-defined trace events. Implementing sys_trace functions directly for specific work queue operations can give you detailed control over individual queue item handling. This method requires configuring your build environment with CONFIG_TRACING_USER enabled and defining custom sys_trace calls within the user space application

#ifdef CONFIG_TRACING_USER
void sys_trace_k_work_queue_user_defined_event(const k_work *work) {
    // Log or output trace for custom events, e.g., enqueue/dequeue times.
}
#endif

Also, by enabling and configuring CONFIG_TIMESLICING, you can also better understand CPU usage patterns across tasks. Combined with work queue tracing, this profiling can help you optimize task priorities and timings based on real-world CPU load patterns observed during testing.