From ce0d41ccaf14139652ba99a61526808df713971a Mon Sep 17 00:00:00 2001 From: Daniel DeGrasse Date: Mon, 10 Jun 2024 19:54:36 +0000 Subject: [PATCH 1/3] tracing: add named event trace Add support for a "named event" trace. This trace is intentionally not used by the system. The purpose of this trace is to allow driver or application developers to quickly add tracing for events for debug purposes, and to provide an example of how tracing subsystems can be extended with additional trace identifiers. Signed-off-by: Daniel DeGrasse --- include/zephyr/tracing/tracing.h | 18 ++++++++++++++++++ scripts/tracing/parse_ctf.py | 5 +++++ subsys/tracing/ctf/ctf_top.c | 11 +++++++++++ subsys/tracing/ctf/ctf_top.h | 8 ++++++++ subsys/tracing/ctf/tracing_ctf.h | 2 ++ subsys/tracing/ctf/tsdl/metadata | 10 ++++++++++ subsys/tracing/sysview/SYSVIEW_Zephyr.txt | 2 ++ subsys/tracing/sysview/sysview.c | 15 +++++++++++++++ subsys/tracing/sysview/tracing_sysview.h | 2 ++ subsys/tracing/sysview/tracing_sysview_ids.h | 2 ++ subsys/tracing/test/tracing_test.h | 2 ++ subsys/tracing/user/tracing_user.h | 2 ++ 12 files changed, 79 insertions(+) diff --git a/include/zephyr/tracing/tracing.h b/include/zephyr/tracing/tracing.h index e969c4eec5cdf5..feb69a74ad72d5 100644 --- a/include/zephyr/tracing/tracing.h +++ b/include/zephyr/tracing/tracing.h @@ -2376,6 +2376,24 @@ /** @} */ /* end of subsys_tracing_apis_socket */ +/** + * @brief Named Tracing APIs + * @defgroup subsys_tracing_apis_named Named tracing APIs + * @{ + */ + +/* + * @brief Called by user to generate named events + * + * @param name name of event. Tracing subsystems may place a limit on + * the length of this string + * @param arg0 arbitrary user-provided data for this event + * @param arg1 arbitrary user-provided data for this event + */ +#define sys_trace_named_event(name, arg0, arg1) + +/** @} */ /* end of subsys_tracing_apis_named */ + #if defined(CONFIG_PERCEPIO_TRACERECORDER) #include "tracing_tracerecorder.h" #else diff --git a/scripts/tracing/parse_ctf.py b/scripts/tracing/parse_ctf.py index 9979623cfa55c0..d25553965c6251 100644 --- a/scripts/tracing/parse_ctf.py +++ b/scripts/tracing/parse_ctf.py @@ -136,6 +136,11 @@ def get_thread(name): c = Fore.MAGENTA print(c + f"{dt} (+{diff_s:.6f} s): {event.name} ({event.payload_field['id']})" + Fore.RESET) + elif event.name in ['named_event']: + name = event.payload_field['name'] + arg0 = event.payload_field['arg0'] + arg1 = event.payload_field['arg1'] + print(f"{dt} (+{diff_s:.6f} s): {event.name} (name: {name}, arg0: {arg0} arg1: {arg1})") else: print(f"{dt} (+{diff_s:.6f} s): {event.name}") diff --git a/subsys/tracing/ctf/ctf_top.c b/subsys/tracing/ctf/ctf_top.c index 12ab43709f3e3b..319ead9134e5e2 100644 --- a/subsys/tracing/ctf/ctf_top.c +++ b/subsys/tracing/ctf/ctf_top.c @@ -746,3 +746,14 @@ void sys_trace_net_tx_time(struct net_pkt *pkt, uint32_t end_time) (uint32_t)tc, (uint32_t)duration_us); } + +void sys_trace_named_event(const char *name, uint32_t arg0, uint32_t arg1) +{ + ctf_bounded_string_t ctf_name = {""}; + + strncpy(ctf_name.buf, name, CTF_MAX_STRING_LEN); + /* Make sure buffer is NULL terminated */ + ctf_name.buf[CTF_MAX_STRING_LEN - 1] = '\0'; + + ctf_named_event(ctf_name, arg0, arg1); +} diff --git a/subsys/tracing/ctf/ctf_top.h b/subsys/tracing/ctf/ctf_top.h index 4929107bfddbc9..b8e677ba8bb3b6 100644 --- a/subsys/tracing/ctf/ctf_top.h +++ b/subsys/tracing/ctf/ctf_top.h @@ -157,6 +157,7 @@ typedef enum { CTF_EVENT_NET_SEND_DATA_EXIT = 0x5F, CTF_EVENT_NET_RX_TIME = 0x60, CTF_EVENT_NET_TX_TIME = 0x61, + CTF_EVENT_NAMED_EVENT = 0x62, } ctf_event_t; @@ -658,4 +659,11 @@ static inline void ctf_top_net_tx_time(int32_t if_index, uint32_t iface, uint32_ if_index, iface, pkt, priority, tc, duration); } +static inline void ctf_named_event(ctf_bounded_string_t name, uint32_t arg0, + uint32_t arg1) +{ + CTF_EVENT(CTF_LITERAL(uint8_t, CTF_EVENT_NAMED_EVENT), name, + arg0, arg1); +} + #endif /* SUBSYS_DEBUG_TRACING_CTF_TOP_H */ diff --git a/subsys/tracing/ctf/tracing_ctf.h b/subsys/tracing/ctf/tracing_ctf.h index ab87411c91196f..1a62a18b02e81a 100644 --- a/subsys/tracing/ctf/tracing_ctf.h +++ b/subsys/tracing/ctf/tracing_ctf.h @@ -592,6 +592,8 @@ void sys_trace_net_send_data_exit(struct net_pkt *pkt, int ret); void sys_trace_net_rx_time(struct net_pkt *pkt, uint32_t end_time); void sys_trace_net_tx_time(struct net_pkt *pkt, uint32_t end_time); +void sys_trace_named_event(const char *name, uint32_t arg0, uint32_t arg1); + #ifdef __cplusplus } #endif diff --git a/subsys/tracing/ctf/tsdl/metadata b/subsys/tracing/ctf/tsdl/metadata index efaa2adc0922eb..c180200337bd38 100644 --- a/subsys/tracing/ctf/tsdl/metadata +++ b/subsys/tracing/ctf/tsdl/metadata @@ -777,3 +777,13 @@ event { uint32_t duration_us; }; }; + +event { + name = named_event; + id = 0x62; + fields := struct { + ctf_bounded_string_t name[20]; + uint32_t arg0; + uint32_t arg1; + }; +}; diff --git a/subsys/tracing/sysview/SYSVIEW_Zephyr.txt b/subsys/tracing/sysview/SYSVIEW_Zephyr.txt index e04d2cfa7c4290..8e33e848804f52 100644 --- a/subsys/tracing/sysview/SYSVIEW_Zephyr.txt +++ b/subsys/tracing/sysview/SYSVIEW_Zephyr.txt @@ -169,3 +169,5 @@ TaskState 0xBF 1=dummy, 2=Waiting, 4=New, 8=Terminated, 16=Suspended, 32=Termina 161 pm_device_runtime_disable dev=%I | Returns %u 162 syscall name=%s + +163 named_event name=%s arg0=%u arg1=%u diff --git a/subsys/tracing/sysview/sysview.c b/subsys/tracing/sysview/sysview.c index 59d426fa7620df..6ca72464bbdf38 100644 --- a/subsys/tracing/sysview/sysview.c +++ b/subsys/tracing/sysview/sysview.c @@ -10,6 +10,7 @@ #include +#define NAMED_EVENT_MAXSTR 20 /* Maximum string length supported by named event */ static uint32_t interrupt; @@ -65,6 +66,20 @@ void sys_trace_idle(void) SEGGER_SYSVIEW_OnIdle(); } +void sys_trace_named_event(const char *name, uint32_t arg0, uint32_t arg1) +{ + /* Based on SEGGER provided code for user defined packets */ + uint8_t a_packet[SEGGER_SYSVIEW_INFO_SIZE + 2 * + SEGGER_SYSVIEW_QUANTA_U32 + NAMED_EVENT_MAXSTR + 1]; + uint8_t *payload; + + payload = SEGGER_SYSVIEW_PREPARE_PACKET(a_packet); + payload = SEGGER_SYSVIEW_EncodeString(payload, name, NAMED_EVENT_MAXSTR); + payload = SEGGER_SYSVIEW_EncodeU32(payload, arg0); + payload = SEGGER_SYSVIEW_EncodeU32(payload, arg1); + SEGGER_SYSVIEW_SendPacket(a_packet, payload, TID_NAMED_EVENT); +} + static int sysview_init(void) { diff --git a/subsys/tracing/sysview/tracing_sysview.h b/subsys/tracing/sysview/tracing_sysview.h index bc01fca62f2446..264777a6f28a67 100644 --- a/subsys/tracing/sysview/tracing_sysview.h +++ b/subsys/tracing/sysview/tracing_sysview.h @@ -639,6 +639,8 @@ void sys_trace_k_thread_ready(struct k_thread *thread); void sys_trace_k_thread_pend(struct k_thread *thread); void sys_trace_k_thread_info(struct k_thread *thread); +void sys_trace_named_event(const char *name, uint32_t arg0, uint32_t arg1); + #define sys_port_trace_pm_system_suspend_enter(ticks) \ SEGGER_SYSVIEW_RecordU32(TID_PM_SYSTEM_SUSPEND, (uint32_t)ticks) #define sys_port_trace_pm_system_suspend_exit(ticks, state) \ diff --git a/subsys/tracing/sysview/tracing_sysview_ids.h b/subsys/tracing/sysview/tracing_sysview_ids.h index 3b8cd8701759a1..d037b172f85419 100644 --- a/subsys/tracing/sysview/tracing_sysview_ids.h +++ b/subsys/tracing/sysview/tracing_sysview_ids.h @@ -155,6 +155,8 @@ extern "C" { #define TID_SYSCALL (130u + TID_OFFSET) +#define TID_NAMED_EVENT (131u + TID_OFFSET) + /* latest ID is 130 */ #ifdef __cplusplus diff --git a/subsys/tracing/test/tracing_test.h b/subsys/tracing/test/tracing_test.h index 3afbb79403667a..f97804c88f56de 100644 --- a/subsys/tracing/test/tracing_test.h +++ b/subsys/tracing/test/tracing_test.h @@ -742,4 +742,6 @@ void sys_trace_k_event_init(struct k_event *event); #define sys_trace_sys_init_enter(...) #define sys_trace_sys_init_exit(...) +#define sys_trace_named_event(name, arg0, arg1) + #endif /* ZEPHYR_TRACE_TEST_H */ diff --git a/subsys/tracing/user/tracing_user.h b/subsys/tracing/user/tracing_user.h index 8d6630895316fb..1d3a28032e3b68 100644 --- a/subsys/tracing/user/tracing_user.h +++ b/subsys/tracing/user/tracing_user.h @@ -390,6 +390,8 @@ void sys_trace_sys_init_exit(const struct init_entry *entry, int level, int resu #define sys_port_trace_net_rx_time(pkt, end_time) #define sys_port_trace_net_tx_time(pkt, end_time) +#define sys_trace_named_event(name, arg0, arg1) + #ifdef __cplusplus } #endif From ba42c6dfc7e6e75adadc5f2265983aa3f109a9dd Mon Sep 17 00:00:00 2001 From: Daniel DeGrasse Date: Mon, 10 Jun 2024 19:56:47 +0000 Subject: [PATCH 2/3] doc: services: document sys_trace_user_event Document availability of sys_trace_user_event, for users who are trying to add custom trace events to their application. Signed-off-by: Daniel DeGrasse --- doc/services/tracing/index.rst | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/doc/services/tracing/index.rst b/doc/services/tracing/index.rst index 2519df266a0a6c..6fb56dd5be4425 100644 --- a/doc/services/tracing/index.rst +++ b/doc/services/tracing/index.rst @@ -32,6 +32,18 @@ interface between payload/format (Top Layer) and the transport mechanics (bottom Layer) is generic and efficient enough to model these. See the *I/O taxonomy* section below. +Named Trace Events +****************** + +Although the user can extend any of the supported serialization formats +to enable additional tracing functions (or provide their own backend), zephyr +also provides one generic named tracing function for convenience purposes, +as well as to demonstrate how tracing frameworks could be extended. + +Users can generate a custom trace event by calling +:c:func:`sys_tracing_named_event`, which takes an event name as well as two +arbitrary 4 byte arguments. Tracing backends may truncate the provided event +name if it is too long for the serialization format they support. Serialization Formats ********************** From 99816b391825f7ef7ef4c282297946102a696ada Mon Sep 17 00:00:00 2001 From: Daniel DeGrasse Date: Mon, 10 Jun 2024 19:57:31 +0000 Subject: [PATCH 3/3] samples: tracing: add usage example for sys_trace_user_event Add usage example for sys_trace_user_event, to demonstrate how users could add tracing functionality to their application. Signed-off-by: Daniel DeGrasse --- samples/subsys/tracing/src/main.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/samples/subsys/tracing/src/main.c b/samples/subsys/tracing/src/main.c index 58523d9ff092a6..27a91d00f55a8b 100644 --- a/samples/subsys/tracing/src/main.c +++ b/samples/subsys/tracing/src/main.c @@ -27,6 +27,7 @@ /* delay between greetings (in ms) */ #define SLEEPTIME 500 +static uint32_t counter; /* * @param my_name thread identification string @@ -42,6 +43,10 @@ void helloLoop(const char *my_name, /* take my semaphore */ k_sem_take(my_sem, K_FOREVER); + /* Provide a named trace, with the counter value */ + sys_trace_named_event("counter_value", counter, 0); + counter++; + /* say "hello" */ tname = k_thread_name_get(k_current_get()); if (tname == NULL) {