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 <daniel.degrasse@nxp.com>

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

scripts/tracing/parse_ctf.py

@@ -136,6 +136,11 @@ def main():
             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}")
 

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);
+}

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 */

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

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;
+	};
+};

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

subsys/tracing/sysview/sysview.c

@@ -10,6 +10,7 @@
 
 #include <SEGGER_SYSVIEW.h>
 
+#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)
 {
 

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

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

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 */

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