net: Collect network packet TX send time

Finalize the CONFIG_NET_CONTEXT_TIMESTAMP support that was started
earlier but never properly finished. We collect network statistics for
TX packet network stack throughput time from when the net_context_send
is called and when the net_pkt was sent out successfully by the network
device driver.

Signed-off-by: Jukka Rissanen <jukka.rissanen@linux.intel.com>

include/net/net_stats.h

@@ -201,6 +201,14 @@ struct net_stats_ipv6_mld {
 	net_stats_t drop;
 };
 
+/**
+ * @brief Network packet transfer times
+ */
+struct net_stats_tx_time {
+	u64_t time_sum;
+	net_stats_t time_count;
+};
+
 /**
  * @brief Traffic class statistics
  */
@@ -209,6 +217,7 @@ struct net_stats_tc {
 		net_stats_t pkts;
 		net_stats_t bytes;
 		u8_t priority;
+		struct net_stats_tx_time tx_time;
 	} sent[NET_TC_TX_COUNT];
 
 	struct {
@@ -273,6 +282,11 @@ struct net_stats {
 	/** Traffic class statistics */
 	struct net_stats_tc tc;
 #endif
+
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+	/** Network packet TX time statistics */
+	struct net_stats_tx_time tx_time;
+#endif
 };
 
 /**

subsys/net/ip/Kconfig

@@ -373,7 +373,8 @@ config NET_CONTEXT_TIMESTAMP
 	bool "Add timestamp support to net_context"
 	select NET_PKT_TIMESTAMP
 	help
-	  It is possible to timestamp outgoing packets.
+	  It is possible to timestamp outgoing packets and get information
+	  about these timestamps.
 
 config NET_TEST
 	bool "Network Testing"
@@ -544,10 +545,21 @@ config NET_PKT_TIMESTAMP
 	  example in gPTP which needs to know how long it takes to send
 	  a network packet.
 
+config NET_PKT_TIMESTAMP_THREAD
+	bool "Create TX timestamp thread"
+	default y if NET_GPTP
+	depends on NET_PKT_TIMESTAMP
+	help
+	  Create a TX timestamp thread that will pass the timestamped network
+	  packets to some other module like gPTP for further processing.
+	  If you just want to timestamp network packets and get information
+	  how long the network packets flow in the system, you can disable
+	  the thread support.
+
 config NET_PKT_TIMESTAMP_STACK_SIZE
 	int "Timestamp thread stack size"
 	default 1024
-	depends on NET_PKT_TIMESTAMP
+	depends on NET_PKT_TIMESTAMP_THREAD
 	help
 	  Set the timestamp thread stack size in bytes. The timestamp
 	  thread waits for timestamped TX frames and calls registered

subsys/net/ip/net_context.c

@@ -1114,6 +1114,23 @@ static int get_context_timepstamp(struct net_context *context,
 #endif
 }
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+int net_context_get_timestamp(struct net_context *context,
+			      struct net_pkt *pkt,
+			      struct net_ptp_time *timestamp)
+{
+	bool is_timestamped;
+
+	get_context_timepstamp(context, &is_timestamped, NULL);
+	if (is_timestamped) {
+		memcpy(timestamp, net_pkt_timestamp(pkt), sizeof(*timestamp));
+		return 0;
+	}
+
+	return -ENOENT;
+}
+#endif /* CONFIG_NET_CONTEXT_TIMESTAMP */
+
 static int context_setup_udp_packet(struct net_context *context,
 				    struct net_pkt *pkt,
 				    const void *buf,
@@ -1348,7 +1365,24 @@ static int context_sendto(struct net_context *context,
 		get_context_timepstamp(context, &timestamp, NULL);
 		if (timestamp) {
 			struct net_ptp_time tp = {
-				.second = k_cycle_get_32(),
+				/* Use the nanosecond field to temporarily
+				 * store the cycle count as it is a 32-bit
+				 * variable. The value is checked in
+				 * net_if.c:net_if_tx()
+				 *
+				 * The net_pkt timestamp field is used in two
+				 * roles here:
+				 * 1) To calculate how long it takes the packet
+				 *    from net_context to be sent by the
+				 *    network device driver.
+				 * 2) gPTP enabled Ethernet device driver will
+				 *    use the value to tell gPTP what time the
+				 *    packet was sent.
+				 *
+				 * Because these two things are happening at
+				 * different times, we can share the variable.
+				 */
+				.nanosecond = k_cycle_get_32(),
 			};
 
 			net_pkt_set_timestamp(pkt, &tp);

subsys/net/ip/net_if.c

@@ -82,7 +82,7 @@ static sys_slist_t link_callbacks;
 static sys_slist_t mcast_monitor_callbacks;
 #endif
 
-#if defined(CONFIG_NET_PKT_TIMESTAMP)
+#if defined(CONFIG_NET_PKT_TIMESTAMP_THREAD)
 #if !defined(CONFIG_NET_PKT_TIMESTAMP_STACK_SIZE)
 #define CONFIG_NET_PKT_TIMESTAMP_STACK_SIZE 1024
 #endif
@@ -97,7 +97,7 @@ static struct k_thread tx_thread_ts;
 /* We keep track of the timestamp callbacks in this list.
  */
 static sys_slist_t timestamp_callbacks;
-#endif /* CONFIG_NET_PKT_TIMESTAMP */
+#endif /* CONFIG_NET_PKT_TIMESTAMP_THREAD */
 
 #if CONFIG_NET_IF_LOG_LEVEL >= LOG_LEVEL_DBG
 #define debug_check_packet(pkt)						\
@@ -142,6 +142,15 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 	struct net_context *context;
 	int status;
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+	/* Timestamp of the current network packet sent */
+	struct net_ptp_time start_timestamp;
+	u32_t curr_time = 0;
+
+	/* We collect send statistics for each socket priority */
+	u8_t pkt_priority;
+#endif
+
 	if (!pkt) {
 		return false;
 	}
@@ -158,7 +167,27 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 			net_pkt_set_queued(pkt, false);
 		}
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+		if (context) {
+			if (net_context_get_timestamp(context, pkt,
+						      &start_timestamp) < 0) {
+				start_timestamp.nanosecond = 0;
+			} else {
+				pkt_priority = net_pkt_priority(pkt);
+			}
+		}
+#endif
+
 		status = net_if_l2(iface)->send(iface, pkt);
+
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+		if (status >= 0 && context) {
+			if (start_timestamp.nanosecond > 0) {
+				curr_time = k_cycle_get_32();
+			}
+		}
+#endif
+
 	} else {
 		/* Drop packet if interface is not up */
 		NET_WARN("iface %p is down", iface);
@@ -176,6 +205,20 @@ static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
 			context, status);
 
 		net_context_send_cb(context, status);
+
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+		if (status >= 0 && start_timestamp.nanosecond &&
+		    curr_time > 0) {
+			/* So we know now how long the network packet was in
+			 * transit from when it was allocated to when we
+			 * got information that it was sent successfully.
+			 */
+			net_stats_update_tc_tx_time(iface,
+						    pkt_priority,
+						    start_timestamp.nanosecond,
+						    curr_time);
+		}
+#endif
 	}
 
 	if (dst->addr) {
@@ -3349,7 +3392,7 @@ bool net_if_is_promisc(struct net_if *iface)
 	return net_if_flag_is_set(iface, NET_IF_PROMISC);
 }
 
-#if defined(CONFIG_NET_PKT_TIMESTAMP)
+#if defined(CONFIG_NET_PKT_TIMESTAMP_THREAD)
 static void net_tx_ts_thread(void)
 {
 	struct net_pkt *pkt;
@@ -3402,7 +3445,7 @@ void net_if_add_tx_timestamp(struct net_pkt *pkt)
 {
 	k_fifo_put(&tx_ts_queue, pkt);
 }
-#endif /* CONFIG_NET_PKT_TIMESTAMP */
+#endif /* CONFIG_NET_PKT_TIMESTAMP_THREAD */
 
 void net_if_init(void)
 {
@@ -3467,13 +3510,13 @@ void net_if_init(void)
 	}
 #endif /* CONFIG_NET_IPV6 */
 
-#if defined(CONFIG_NET_PKT_TIMESTAMP)
+#if defined(CONFIG_NET_PKT_TIMESTAMP_THREAD)
 	k_thread_create(&tx_thread_ts, tx_ts_stack,
 			K_THREAD_STACK_SIZEOF(tx_ts_stack),
 			(k_thread_entry_t)net_tx_ts_thread,
 			NULL, NULL, NULL, K_PRIO_COOP(1), 0, 0);
 	k_thread_name_set(&tx_thread_ts, "tx_tstamp");
-#endif /* CONFIG_NET_PKT_TIMESTAMP */
+#endif /* CONFIG_NET_PKT_TIMESTAMP_THREAD */
 
 #if defined(CONFIG_NET_VLAN)
 	/* Make sure that we do not have too many network interfaces

subsys/net/ip/net_private.h

@@ -57,6 +57,12 @@ char *net_sprint_addr(sa_family_t af, const void *addr);
 
 #define net_sprint_ipv6_addr(_addr) net_sprint_addr(AF_INET6, _addr)
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP)
+int net_context_get_timestamp(struct net_context *context,
+			      struct net_pkt *pkt,
+			      struct net_ptp_time *timestamp);
+#endif
+
 #if defined(CONFIG_NET_GPTP)
 /**
  * @brief Initialize Precision Time Protocol Layer.

subsys/net/ip/net_stats.h

@@ -9,6 +9,8 @@
 
 #if defined(CONFIG_NET_STATISTICS)
 
+#include <stdlib.h>
+
 #include <net/net_ip.h>
 #include <net/net_stats.h>
 #include <net/net_if.h>
@@ -308,6 +310,28 @@ static inline void net_stats_update_ipv6_mld_drop(struct net_if *iface)
 #define net_stats_update_ipv6_mld_drop(iface)
 #endif /* CONFIG_NET_STATISTICS_MLD */
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP) && defined(CONFIG_NET_STATISTICS)
+static inline void net_stats_update_tx_time(struct net_if *iface,
+					    u32_t start_time,
+					    u32_t end_time)
+{
+	u32_t diff = abs(end_time - start_time);
+
+	UPDATE_STAT(iface, stats.tx_time.time_sum +=
+		    SYS_CLOCK_HW_CYCLES_TO_NS64(diff) / 1000);
+	UPDATE_STAT(iface, stats.tx_time.time_count += 1);
+}
+#else
+static inline void net_stats_update_tx_time(struct net_if *iface,
+					    u32_t start_time,
+					    u32_t end_time)
+{
+	ARG_UNUSED(iface);
+	ARG_UNUSED(start_time);
+	ARG_UNUSED(end_time);
+}
+#endif /* CONFIG_NET_CONTEXT_TIMESTAMP && STATISTICS */
+
 #if (NET_TC_COUNT > 1) && defined(CONFIG_NET_STATISTICS)
 static inline void net_stats_update_tc_sent_pkt(struct net_if *iface, u8_t tc)
 {
@@ -326,6 +350,33 @@ static inline void net_stats_update_tc_sent_priority(struct net_if *iface,
 	UPDATE_STAT(iface, stats.tc.sent[tc].priority = priority);
 }
 
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP) && defined(CONFIG_NET_STATISTICS)
+static inline void net_stats_update_tc_tx_time(struct net_if *iface,
+					       u8_t tc,
+					       u32_t start_time,
+					       u32_t end_time)
+{
+	u32_t diff = abs(end_time - start_time);
+
+	UPDATE_STAT(iface, stats.tc.sent[tc].tx_time.time_sum +=
+		    SYS_CLOCK_HW_CYCLES_TO_NS64(diff) / 1000);
+	UPDATE_STAT(iface, stats.tc.sent[tc].tx_time.time_count += 1);
+
+	net_stats_update_tx_time(iface, start_time, end_time);
+}
+#else
+static inline void net_stats_update_tc_tx_time(struct net_if *iface,
+					       u8_t tc,
+					       u32_t start_time,
+					       u32_t end_time)
+{
+	ARG_UNUSED(iface);
+	ARG_UNUSED(tc);
+	ARG_UNUSED(start_time);
+	ARG_UNUSED(end_time);
+}
+#endif /* CONFIG_NET_CONTEXT_TIMESTAMP && CONFIG_NET_STATISTICS */
+
 static inline void net_stats_update_tc_recv_pkt(struct net_if *iface, u8_t tc)
 {
 	UPDATE_STAT(iface, stats.tc.recv[tc].pkts++);
@@ -349,6 +400,29 @@ static inline void net_stats_update_tc_recv_priority(struct net_if *iface,
 #define net_stats_update_tc_recv_pkt(iface, tc)
 #define net_stats_update_tc_recv_bytes(iface, tc, bytes)
 #define net_stats_update_tc_recv_priority(iface, tc, priority)
+
+#if defined(CONFIG_NET_CONTEXT_TIMESTAMP) && defined(CONFIG_NET_STATISTICS)
+static inline void net_stats_update_tc_tx_time(struct net_if *iface,
+					       u8_t pkt_priority,
+					       u32_t start_time,
+					       u32_t end_time)
+{
+	ARG_UNUSED(pkt_priority);
+
+	net_stats_update_tx_time(iface, start_time, end_time);
+}
+#else
+static inline void net_stats_update_tc_tx_time(struct net_if *iface,
+					       u8_t pkt_priority,
+					       u32_t start_time,
+					       u32_t end_time)
+{
+	ARG_UNUSED(iface);
+	ARG_UNUSED(pkt_priority);
+	ARG_UNUSED(start_time);
+	ARG_UNUSED(end_time);
+}
+#endif /* CONFIG_NET_CONTEXT_TIMESTAMP && CONFIG_NET_STATISTICS */
 #endif /* NET_TC_COUNT > 1 */
 
 #if defined(CONFIG_NET_STATISTICS_PERIODIC_OUTPUT)