tracing: add user event trace

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

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

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

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}")
 

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 @@
 	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 @@
 		  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 @@
 	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