net: tracing: Add RX time tracing

RX time tracing tells how long it took from network packet creation to when the stack got rid of it. So the network device driver allocates net packet, this is the start time. The end time is when the packet is fully processed. Currently the limitation is that the RX time duration is used for network packets that are tied to an open socket. Signed-off-by: Jukka Rissanen <[email protected]>
ashiroji · Aug 20, 2024 · a679dd9 · a679dd9
1 parent 4911a4f
commit a679dd9
Show file tree

Hide file tree

Showing 9 changed files with 75 additions and 5 deletions.
diff --git a/include/zephyr/net/net_pkt.h b/include/zephyr/net/net_pkt.h
@@ -123,7 +123,8 @@ struct net_pkt {
 	struct net_ptp_time timestamp;
 #endif
 
-#if defined(CONFIG_NET_PKT_RXTIME_STATS) || defined(CONFIG_NET_PKT_TXTIME_STATS)
+#if defined(CONFIG_NET_PKT_RXTIME_STATS) || defined(CONFIG_NET_PKT_TXTIME_STATS) || \
+	defined(CONFIG_TRACING_NET_CORE)
 	struct {
 		/** Create time in cycles */
 		uint32_t create_time;
@@ -1107,7 +1108,9 @@ static inline void net_pkt_set_timestamp_ns(struct net_pkt *pkt, net_time_t time
 }
 #endif /* CONFIG_NET_PKT_TIMESTAMP || CONFIG_NET_PKT_TXTIME */
 
-#if defined(CONFIG_NET_PKT_RXTIME_STATS) || defined(CONFIG_NET_PKT_TXTIME_STATS)
+#if defined(CONFIG_NET_PKT_RXTIME_STATS) || defined(CONFIG_NET_PKT_TXTIME_STATS) || \
+	defined(CONFIG_TRACING_NET_CORE)
+
 static inline uint32_t net_pkt_create_time(struct net_pkt *pkt)
 {
 	return pkt->create_time;
@@ -1132,7 +1135,9 @@ static inline void net_pkt_set_create_time(struct net_pkt *pkt,
 	ARG_UNUSED(pkt);
 	ARG_UNUSED(create_time);
 }
-#endif /* CONFIG_NET_PKT_RXTIME_STATS || CONFIG_NET_PKT_TXTIME_STATS */
+#endif /* CONFIG_NET_PKT_RXTIME_STATS || CONFIG_NET_PKT_TXTIME_STATS ||
+	* CONFIG_TRACING_NET_CORE
+	*/
 
 /**
  * @deprecated Use @ref net_pkt_timestamp or @ref net_pkt_timestamp_ns instead.

diff --git a/include/zephyr/tracing/tracing.h b/include/zephyr/tracing/tracing.h
@@ -2062,6 +2062,13 @@
  */
 #define sys_port_trace_net_send_data_exit(pkt, ret)
 
+/**
+ * @brief Trace network data receive time
+ * @param pkt Received network packet
+ * @param end_time When the RX processing stopped for this pkt (in ticks)
+ */
+#define sys_port_trace_net_rx_time(pkt, end_time)
+
 /** @} */ /* end of subsys_tracing_apis_net */
 
 /**

diff --git a/subsys/net/lib/sockets/sockets.c b/subsys/net/lib/sockets/sockets.c
@@ -1265,6 +1265,8 @@ void net_socket_update_tc_rx_time(struct net_pkt *pkt, uint32_t end_tick)
 				    net_pkt_create_time(pkt),
 				    end_tick);
 
+	SYS_PORT_TRACING_FUNC(net, rx_time, pkt, end_tick);
+
 	if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS_DETAIL)) {
 		uint32_t val, prev = net_pkt_create_time(pkt);
 		int i;
@@ -1596,7 +1598,8 @@ static inline ssize_t zsock_recv_dgram(struct net_context *ctx,
 		}
 	}
 
-	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());
 	}
@@ -1669,7 +1672,8 @@ static size_t zsock_recv_stream_immediate(struct net_context *ctx, uint8_t **buf
 					sock_set_eof(ctx);
 				}
 
-				if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS)) {
+				if (IS_ENABLED(CONFIG_NET_PKT_RXTIME_STATS) ||
+				    IS_ENABLED(CONFIG_TRACING_NET_CORE)) {
 					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
@@ -690,3 +690,31 @@ void sys_trace_net_send_data_exit(struct net_pkt *pkt, int ret)
 				   (uint32_t)(uintptr_t)pkt,
 				   (int32_t)ret);
 }
+
+void sys_trace_net_rx_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_rx_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
@@ -155,6 +155,7 @@ typedef enum {
 	CTF_EVENT_NET_RECV_DATA_EXIT = 0x5D,
 	CTF_EVENT_NET_SEND_DATA_ENTER = 0x5E,
 	CTF_EVENT_NET_SEND_DATA_EXIT = 0x5F,
+	CTF_EVENT_NET_RX_TIME = 0x60,
 
 } ctf_event_t;
 
@@ -642,4 +643,11 @@ static inline void ctf_top_net_send_data_exit(int32_t if_index, uint32_t iface,
 		  if_index, iface, pkt, ret);
 }
 
+static inline void ctf_top_net_rx_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_RX_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
@@ -577,6 +577,8 @@ void sys_trace_socket_socketpair_exit(int sock_A, int sock_B, int ret);
 	sys_trace_net_send_data_enter(pkt)
 #define sys_port_trace_net_send_data_exit(pkt, 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)
 
 struct net_if;
 struct net_pkt;
@@ -585,6 +587,7 @@ void sys_trace_net_recv_data_enter(struct net_if *iface, struct net_pkt *pkt);
 void sys_trace_net_recv_data_exit(struct net_if *iface, struct net_pkt *pkt, int ret);
 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);
 
 #ifdef __cplusplus
 }

diff --git a/subsys/tracing/ctf/tsdl/metadata b/subsys/tracing/ctf/tsdl/metadata
@@ -751,3 +751,16 @@ event {
 		int32_t result;
 	};
 };
+
+event {
+	name = net_rx_time;
+	id = 0x60;
+	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
@@ -736,6 +736,7 @@ void sys_trace_k_event_init(struct k_event *event);
 #define sys_port_trace_net_recv_data_exit(iface, pkt, ret)
 #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_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
@@ -387,6 +387,7 @@ void sys_trace_sys_init_exit(const struct init_entry *entry, int level, int resu
 #define sys_port_trace_net_recv_data_exit(iface, pkt, ret)
 #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)
 
 #ifdef __cplusplus
 }