net: tracing: Add TX time tracing

TX time tracing tells how long it took from network packet creation to when the stack got rid of it. So the network stack allocates net packet, this is the start time. The end time is when the packet is fully processed (sent) by the network device driver. Signed-off-by: Jukka Rissanen <[email protected]>
ashiroji · Aug 20, 2024 · 0b985ac · 0b985ac
1 parent a679dd9
commit 0b985ac
Show file tree

Hide file tree

Showing 10 changed files with 73 additions and 5 deletions.
diff --git a/include/zephyr/tracing/tracing.h b/include/zephyr/tracing/tracing.h
@@ -2069,6 +2069,13 @@
  */
 #define sys_port_trace_net_rx_time(pkt, end_time)
 
+/**
+ * @brief Trace network data sent time
+ * @param pkt Sent network packet
+ * @param end_time When the TX processing stopped for this pkt (in ticks)
+ */
+#define sys_port_trace_net_tx_time(pkt, end_time)
+
 /** @} */ /* end of subsys_tracing_apis_net */
 
 /**

diff --git a/subsys/net/ip/net_if.c b/subsys/net/ip/net_if.c
@@ -247,7 +247,8 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 	context = net_pkt_context(pkt);
 
 	if (net_if_flag_is_set(iface, NET_IF_LOWER_UP)) {
-		if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS)) {
+		if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS) ||
+		    IS_ENABLED(CONFIG_TRACING_NET_CORE)) {
 			pkt_priority = net_pkt_priority(pkt);
 
 			if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS_DETAIL)) {
@@ -262,7 +263,8 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 		status = net_if_l2(iface)->send(iface, pkt);
 		net_if_tx_unlock(iface);
 
-		if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS)) {
+		if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS) ||
+		    IS_ENABLED(CONFIG_TRACING_NET_CORE)) {
 			uint32_t end_tick = k_cycle_get_32();
 
 			net_pkt_set_tx_stats_tick(pkt, end_tick);
@@ -272,6 +274,8 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 						    create_time,
 						    end_tick);
 
+			SYS_PORT_TRACING_FUNC(net, tx_time, pkt, end_tick);
+
 			if (IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS_DETAIL)) {
 				update_txtime_stats_detail(
 					pkt,

diff --git a/subsys/net/ip/net_pkt.c b/subsys/net/ip/net_pkt.c
@@ -1274,7 +1274,8 @@ static struct net_pkt *pkt_alloc(struct k_mem_slab *slab, k_timeout_t timeout)
 	}
 
 	if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS) ||
-	    IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS)) {
+	    IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS) ||
+	    IS_ENABLED(CONFIG_TRACING_NET_CORE)) {
 		create_time = k_cycle_get_32();
 	} else {
 		ARG_UNUSED(create_time);
@@ -1313,7 +1314,8 @@ static struct net_pkt *pkt_alloc(struct k_mem_slab *slab, k_timeout_t timeout)
 	}
 
 	if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS) ||
-	    IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS)) {
+	    IS_ENABLED(CONFIG_NET_PKT_TXTIME_STATS) ||
+	    IS_ENABLED(CONFIG_TRACING_NET_CORE)) {
 		net_pkt_set_create_time(pkt, create_time);
 	}
 

diff --git a/subsys/net/lib/sockets/sockets_packet.c b/subsys/net/lib/sockets/sockets_packet.c
@@ -345,7 +345,8 @@ ssize_t zpacket_recvfrom_ctx(struct net_context *ctx, void *buf, size_t max_len,
 		zpacket_set_source_addr(ctx, pkt, src_addr, addrlen);
 	}
 
-	if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS) &&
+	if ((IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS) ||
+	     IS_ENABLED(CONFIG_TRACING_NET_CORE)) &&
 	    !(flags & ZSOCK_MSG_PEEK)) {
 		net_socket_update_tc_rx_time(pkt, k_cycle_get_32());
 	}

diff --git a/subsys/tracing/ctf/ctf_top.c b/subsys/tracing/ctf/ctf_top.c
@@ -718,3 +718,31 @@ void sys_trace_net_rx_time(struct net_pkt *pkt, uint32_t end_time)
 			    (uint32_t)tc,
 			    (uint32_t)duration_us);
 }
+
+void sys_trace_net_tx_time(struct net_pkt *pkt, uint32_t end_time)
+{
+	struct net_if *iface;
+	int ifindex;
+	uint32_t diff;
+	int tc;
+	uint32_t duration_us;
+
+	iface = net_pkt_iface(pkt);
+	if (iface == NULL) {
+		ifindex = -1;
+		tc = 0;
+		duration_us = 0;
+	} else {
+		ifindex = net_if_get_by_iface(iface);
+		diff = end_time - net_pkt_create_time(pkt);
+		tc = net_rx_priority2tc(net_pkt_priority(pkt));
+		duration_us = k_cyc_to_ns_floor64(diff) / 1000U;
+	}
+
+	ctf_top_net_tx_time((int32_t)ifindex,
+			    (uint32_t)(uintptr_t)iface,
+			    (uint32_t)(uintptr_t)pkt,
+			    (uint32_t)net_pkt_priority(pkt),
+			    (uint32_t)tc,
+			    (uint32_t)duration_us);
+}
diff --git a/subsys/tracing/ctf/ctf_top.h b/subsys/tracing/ctf/ctf_top.h
@@ -156,6 +156,7 @@ typedef enum {
 	CTF_EVENT_NET_SEND_DATA_ENTER = 0x5E,
 	CTF_EVENT_NET_SEND_DATA_EXIT = 0x5F,
 	CTF_EVENT_NET_RX_TIME = 0x60,
+	CTF_EVENT_NET_TX_TIME = 0x61,
 
 } ctf_event_t;
 
@@ -650,4 +651,11 @@ static inline void ctf_top_net_rx_time(int32_t if_index, uint32_t iface, uint32_
 		  if_index, iface, pkt, priority, tc, duration);
 }
 
+static inline void ctf_top_net_tx_time(int32_t if_index, uint32_t iface, uint32_t pkt,
+				       uint32_t priority, uint32_t tc, uint32_t duration)
+{
+	CTF_EVENT(CTF_LITERAL(uint8_t, CTF_EVENT_NET_TX_TIME),
+		  if_index, iface, pkt, priority, tc, duration);
+}
+
 #endif /* SUBSYS_DEBUG_TRACING_CTF_TOP_H */
diff --git a/subsys/tracing/ctf/tracing_ctf.h b/subsys/tracing/ctf/tracing_ctf.h
@@ -579,6 +579,8 @@ void sys_trace_socket_socketpair_exit(int sock_A, int sock_B, int ret);
 	sys_trace_net_send_data_exit(pkt, ret)
 #define sys_port_trace_net_rx_time(pkt, end_time)		\
 	sys_trace_net_rx_time(pkt, end_time)
+#define sys_port_trace_net_tx_time(pkt, end_time)		\
+	sys_trace_net_tx_time(pkt, end_time)
 
 struct net_if;
 struct net_pkt;
@@ -588,6 +590,7 @@ void sys_trace_net_recv_data_exit(struct net_if *iface, struct net_pkt *pkt, int
 void sys_trace_net_send_data_enter(struct net_pkt *pkt);
 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);
 
 #ifdef __cplusplus
 }

diff --git a/subsys/tracing/ctf/tsdl/metadata b/subsys/tracing/ctf/tsdl/metadata
@@ -764,3 +764,16 @@ event {
 		uint32_t duration_us;
 	};
 };
+
+event {
+	name = net_tx_time;
+	id = 0x61;
+	fields := struct {
+		int32_t if_index;
+		uint32_t iface;
+		uint32_t pkt;
+		uint32_t priority;
+		uint32_t traffic_class;
+		uint32_t duration_us;
+	};
+};
diff --git a/subsys/tracing/test/tracing_test.h b/subsys/tracing/test/tracing_test.h
@@ -737,6 +737,7 @@ void sys_trace_k_event_init(struct k_event *event);
 #define sys_port_trace_net_send_data_enter(pkt)
 #define sys_port_trace_net_send_data_exit(pkt, ret)
 #define sys_port_trace_net_rx_time(pkt, end_time)
+#define sys_port_trace_net_tx_time(pkt, end_time)
 
 #define sys_trace_sys_init_enter(...)
 #define sys_trace_sys_init_exit(...)

diff --git a/subsys/tracing/user/tracing_user.h b/subsys/tracing/user/tracing_user.h
@@ -388,6 +388,7 @@ void sys_trace_sys_init_exit(const struct init_entry *entry, int level, int resu
 #define sys_port_trace_net_send_data_enter(pkt)
 #define sys_port_trace_net_send_data_exit(pkt, ret)
 #define sys_port_trace_net_rx_time(pkt, end_time)
+#define sys_port_trace_net_tx_time(pkt, end_time)
 
 #ifdef __cplusplus
 }