[RFC] latencystats: performance overhaul

[RFC] latencystats: performance overhaul

[Stephen Hemminger]

The latencystats library had multiple performance issues.
The biggest one is the use of global data and lock for all ports
and queues. Rewrite it to use per-queue statistics.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 335 +++++++++++++++-------------
 1 file changed, 184 insertions(+), 151 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 4ea9b0d75b..bce2bec859 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,29 +2,18 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
-#include <math.h>
-
-#include <rte_string_fns.h>
 #include <rte_mbuf_dyn.h>
 #include <rte_log.h>
+#include <rte_stdatomic.h>
 #include <rte_cycles.h>
 #include <rte_ethdev.h>
 #include <rte_metrics.h>
 #include <rte_memzone.h>
 #include <rte_lcore.h>
+#include <rte_time.h>
 
 #include "rte_latencystats.h"
 
-/** Nano seconds per second */
-#define NS_PER_SEC 1E9
-
-/** Clock cycles per nano second */
-static uint64_t
-latencystat_cycles_per_ns(void)
-{
-	return rte_get_timer_hz() / NS_PER_SEC;
-}
-
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
 #define LATENCY_STATS_LOG(level, ...) \
@@ -40,28 +29,32 @@ timestamp_dynfield(struct rte_mbuf *mbuf)
 			timestamp_dynfield_offset, rte_mbuf_timestamp_t *);
 }
 
-static const char *MZ_RTE_LATENCY_STATS = "rte_latencystats";
+static const char MZ_RTE_LATENCY_STATS[] = "rte_latencystats";
 static int latency_stats_index;
 static uint64_t samp_intvl;
-static uint64_t timer_tsc;
-static uint64_t prev_tsc;
 
+/* Per queue latency information (in cycles) */
 struct rte_latency_stats {
-	float min_latency; /**< Minimum latency in nano seconds */
-	float avg_latency; /**< Average latency in nano seconds */
-	float max_latency; /**< Maximum latency in nano seconds */
-	float jitter; /** Latency variation */
-	rte_spinlock_t lock; /** Latency calculation lock */
-};
-
-static struct rte_latency_stats *glob_stats;
-
-struct rxtx_cbs {
+	RTE_ATOMIC(uint64_t) min_latency; /* Minimum latency */
+	RTE_ATOMIC(uint64_t) avg_latency; /* Average latency */
+	RTE_ATOMIC(uint64_t) max_latency; /* Maximum latency */
+	RTE_ATOMIC(uint64_t) jitter;      /* Latency variation */
+} __rte_cache_aligned;
+
+/* per queue info stored in memxone */
+static struct {
+	struct rte_latency_stats stats[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
+} *latency_stats;
+
+static struct {
+	uint64_t prev_tsc;
 	const struct rte_eth_rxtx_callback *cb;
-};
+} rx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 
-static struct rxtx_cbs rx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
-static struct rxtx_cbs tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
+static struct {
+	uint64_t prev_latency;
+	const struct rte_eth_rxtx_callback *cb;
+} tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 
 struct latency_stats_nameoff {
 	char name[RTE_ETH_XSTATS_NAME_SIZE];
@@ -75,51 +68,87 @@ static const struct latency_stats_nameoff lat_stats_strings[] = {
 	{"jitter_ns", offsetof(struct rte_latency_stats, jitter)},
 };
 
-#define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
-				sizeof(lat_stats_strings[0]))
+#define NUM_LATENCY_STATS RTE_DIM(lat_stats_strings)
 
-int32_t
-rte_latencystats_update(void)
+static inline uint64_t
+cycles_to_ns(uint64_t cycles)
 {
-	unsigned int i;
-	float *stats_ptr = NULL;
-	uint64_t values[NUM_LATENCY_STATS] = {0};
+	return (cycles * NSEC_PER_SEC) / rte_get_tsc_hz();
+}
+
+static inline uint64_t
+latencystat_read_ns(const uint64_t *stat_ptr)
+{
+	return cycles_to_ns(rte_atomic_load_explicit(stat_ptr, rte_memory_order_relaxed));
+}
+
+
+/* aggregate data across all ports and queues */
+static void
+latencystats_collect(uint64_t *values)
+{
+	unsigned int i, samples = 0;
+	uint16_t pid, qid;
 	int ret;
+	struct rte_latency_stats sum = { };
+
+	RTE_ETH_FOREACH_DEV(pid) {
+		struct rte_eth_dev_info dev_info;
+
+		ret = rte_eth_dev_info_get(pid, &dev_info);
+		if (ret != 0) {
+			LATENCY_STATS_LOG(ERR,
+				"Error during getting device (port %u) info: %s",
+				pid, strerror(-ret));
+			continue;
+		}
+
+		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
+			const struct rte_latency_stats *stats = &latency_stats->stats[pid][qid];
+			uint64_t l;
+
+			l = latencystat_read_ns(&stats->min_latency);
+			if (l != 0 && (sum.min_latency == 0 || l < sum.min_latency))
+				sum.min_latency = l;
+
+			l = latencystat_read_ns(&stats->max_latency);
+			if (l < sum.max_latency)
+				sum.max_latency = l;
+
+			sum.avg_latency += latencystat_read_ns(&stats->avg_latency);
+			sum.jitter += latencystat_read_ns(&stats->jitter);
+			++samples;
+		}
 
-	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i] = (uint64_t)floor((*stats_ptr)/
-				latencystat_cycles_per_ns());
 	}
 
-	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
-					latency_stats_index,
-					values, NUM_LATENCY_STATS);
-	if (ret < 0)
-		LATENCY_STATS_LOG(INFO, "Failed to push the stats");
+	/* adjust averages based on number of samples */
+	if (samples > 0) {
+		sum.avg_latency /= samples;
+		sum.jitter /= samples;
+	}
 
-	return ret;
+	/* convert cycle counts to ns */
+	for (i = 0; i < NUM_LATENCY_STATS; i++) {
+		uint64_t *stats_ptr = RTE_PTR_ADD(&sum, lat_stats_strings[i].offset);
+
+		values[i] = *stats_ptr;
+	}
 }
 
-static void
-rte_latencystats_fill_values(struct rte_metric_value *values)
+int32_t
+rte_latencystats_update(void)
 {
-	unsigned int i;
-	float *stats_ptr = NULL;
+	uint64_t values[NUM_LATENCY_STATS] = { 0 };
 
-	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i].key = i;
-		values[i].value = (uint64_t)floor((*stats_ptr)/
-						latencystat_cycles_per_ns());
-	}
+	latencystats_collect(values);
+
+	return rte_metrics_update_values(RTE_METRICS_GLOBAL, latency_stats_index,
+					values, NUM_LATENCY_STATS);
 }
 
 static uint16_t
-add_time_stamps(uint16_t pid __rte_unused,
-		uint16_t qid __rte_unused,
+add_time_stamps(uint16_t pid, uint16_t qid,
 		struct rte_mbuf **pkts,
 		uint16_t nb_pkts,
 		uint16_t max_pkts __rte_unused,
@@ -127,55 +156,47 @@ add_time_stamps(uint16_t pid __rte_unused,
 {
 	unsigned int i;
 	uint64_t diff_tsc, now;
+	uint64_t *prev_tsc = &rx_cbs[pid][qid].prev_tsc;
 
 	/*
 	 * For every sample interval,
 	 * time stamp is marked on one received packet.
 	 */
-	now = rte_rdtsc();
 	for (i = 0; i < nb_pkts; i++) {
-		diff_tsc = now - prev_tsc;
-		timer_tsc += diff_tsc;
+		if ((pkts[i]->ol_flags & timestamp_dynflag) != 0)
+			continue;
 
-		if ((pkts[i]->ol_flags & timestamp_dynflag) == 0
-				&& (timer_tsc >= samp_intvl)) {
+		now = rte_rdtsc();
+		diff_tsc = now - *prev_tsc;
+		if (diff_tsc >= samp_intvl) {
 			*timestamp_dynfield(pkts[i]) = now;
 			pkts[i]->ol_flags |= timestamp_dynflag;
-			timer_tsc = 0;
+			*prev_tsc = now;
+			break;
 		}
-		prev_tsc = now;
-		now = rte_rdtsc();
 	}
 
 	return nb_pkts;
 }
 
 static uint16_t
-calc_latency(uint16_t pid __rte_unused,
-		uint16_t qid __rte_unused,
-		struct rte_mbuf **pkts,
-		uint16_t nb_pkts,
-		void *_ __rte_unused)
+calc_latency(uint16_t pid, uint16_t qid, struct rte_mbuf **pkts, uint16_t nb_pkts, void *arg)
 {
-	unsigned int i, cnt = 0;
-	uint64_t now;
-	float latency[nb_pkts];
-	static float prev_latency;
-	/*
-	 * Alpha represents degree of weighting decrease in EWMA,
-	 * a constant smoothing factor between 0 and 1. The value
-	 * is used below for measuring average latency.
-	 */
-	const float alpha = 0.2;
+	struct rte_latency_stats *stats = arg;
+	unsigned int i;
+	uint64_t now, *prev;
 
+	prev = &tx_cbs[pid][qid].prev_latency;
 	now = rte_rdtsc();
 	for (i = 0; i < nb_pkts; i++) {
-		if (pkts[i]->ol_flags & timestamp_dynflag)
-			latency[cnt++] = now - *timestamp_dynfield(pkts[i]);
-	}
+		uint64_t latency;
+		int64_t delta;
+
+		if ((pkts[i]->ol_flags & timestamp_dynflag) == 0)
+			continue;
+
+		latency = now - *timestamp_dynfield(pkts[i]);
 
-	rte_spinlock_lock(&glob_stats->lock);
-	for (i = 0; i < cnt; i++) {
 		/*
 		 * The jitter is calculated as statistical mean of interpacket
 		 * delay variation. The "jitter estimate" is computed by taking
@@ -187,24 +208,26 @@ calc_latency(uint16_t pid __rte_unused,
 		 * Reference: Calculated as per RFC 5481, sec 4.1,
 		 * RFC 3393 sec 4.5, RFC 1889 sec.
 		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency[i])
-					- glob_stats->jitter)/16;
-		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] < glob_stats->min_latency)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] > glob_stats->max_latency)
-			glob_stats->max_latency = latency[i];
+		delta = *prev - latency;
+		*prev = latency;
+		rte_atomic_store_explicit(&stats->jitter,
+					  stats->jitter + (delta - stats->jitter) / 16,
+					  rte_memory_order_relaxed);
+
+		if (stats->min_latency == 0 || latency < stats->min_latency)
+			rte_atomic_store_explicit(&stats->min_latency, latency, rte_memory_order_relaxed);
+		else if (latency > stats->max_latency)
+			rte_atomic_store_explicit(&stats->max_latency, latency, rte_memory_order_relaxed);
+
 		/*
 		 * The average latency is measured using exponential moving
 		 * average, i.e. using EWMA
 		 * https://en.wikipedia.org/wiki/Moving_average
 		 */
-		glob_stats->avg_latency +=
-			alpha * (latency[i] - glob_stats->avg_latency);
-		prev_latency = latency[i];
+		delta = latency - stats->avg_latency;
+		latency = (delta + 3 * stats->avg_latency) / 4;
+		rte_atomic_store_explicit(&stats->avg_latency, latency, rte_memory_order_relaxed);
 	}
-	rte_spinlock_unlock(&glob_stats->lock);
 
 	return nb_pkts;
 }
@@ -214,38 +237,34 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		rte_latency_stats_flow_type_fn user_cb)
 {
 	unsigned int i;
-	uint16_t pid;
-	uint16_t qid;
-	struct rxtx_cbs *cbs = NULL;
-	const char *ptr_strings[NUM_LATENCY_STATS] = {0};
-	const struct rte_memzone *mz = NULL;
-	const unsigned int flags = 0;
+	uint16_t pid, qid;
+	const char *ptr_strings[NUM_LATENCY_STATS];
+	const struct rte_memzone *mz;
 	int ret;
 
 	if (rte_memzone_lookup(MZ_RTE_LATENCY_STATS))
 		return -EEXIST;
 
-	/** Allocate stats in shared memory fo multi process support */
-	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*glob_stats),
-					rte_socket_id(), flags);
+	/* Allocate stats in shared memory for multi process support */
+	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*latency_stats),
+					rte_socket_id(), 0);
 	if (mz == NULL) {
 		LATENCY_STATS_LOG(ERR, "Cannot reserve memory: %s:%d",
 			__func__, __LINE__);
 		return -ENOMEM;
 	}
 
-	glob_stats = mz->addr;
-	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	latency_stats = mz->addr;
+	samp_intvl = (app_samp_intvl * NSEC_PER_SEC) / rte_get_tsc_hz();
 
-	/** Register latency stats with stats library */
+	/* Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
 		ptr_strings[i] = lat_stats_strings[i].name;
 
 	latency_stats_index = rte_metrics_reg_names(ptr_strings,
 							NUM_LATENCY_STATS);
 	if (latency_stats_index < 0) {
-		LATENCY_STATS_LOG(DEBUG,
+		LATENCY_STATS_LOG(ERR,
 			"Failed to register latency stats names");
 		return -1;
 	}
@@ -259,13 +278,14 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		return -rte_errno;
 	}
 
-	/** Register Rx/Tx callbacks */
+	/* Register Rx/Tx callbacks */
 	RTE_ETH_FOREACH_DEV(pid) {
 		struct rte_eth_dev_info dev_info;
+		const struct rte_eth_rxtx_callback *cb;
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -273,23 +293,25 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		}
 
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
-			cbs = &rx_cbs[pid][qid];
-			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
-					add_time_stamps, user_cb);
-			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+			cb = rte_eth_add_first_rx_callback(pid, qid, add_time_stamps, user_cb);
+			if (cb)
+				rx_cbs[pid][qid].cb = cb;
+			else
+				LATENCY_STATS_LOG(NOTICE,
+						  "Failed to register Rx callback for pid=%d, qid=%d",
+						  pid, qid);
 		}
+
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
-			cbs = &tx_cbs[pid][qid];
-			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
-					calc_latency, user_cb);
-			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+			cb = rte_eth_add_tx_callback(pid, qid, calc_latency, user_cb);
+			if (cb)
+				tx_cbs[pid][qid].cb = cb;
+			else
+				LATENCY_STATS_LOG(NOTICE,
+						  "Failed to register Tx callback for pid=%d, qid=%d",
+						  pid, qid);
 		}
+
 	}
 	return 0;
 }
@@ -297,19 +319,18 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 int
 rte_latencystats_uninit(void)
 {
-	uint16_t pid;
-	uint16_t qid;
-	int ret = 0;
-	struct rxtx_cbs *cbs = NULL;
-	const struct rte_memzone *mz = NULL;
+	const struct rte_memzone *mz;
+	uint16_t pid, qid;
+	int ret;
 
-	/** De register Rx/Tx callbacks */
+	/* De register Rx/Tx callbacks */
 	RTE_ETH_FOREACH_DEV(pid) {
 		struct rte_eth_dev_info dev_info;
+		const struct rte_eth_rxtx_callback *cb;
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -317,27 +338,29 @@ rte_latencystats_uninit(void)
 		}
 
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
-			cbs = &rx_cbs[pid][qid];
-			ret = rte_eth_remove_rx_callback(pid, qid, cbs->cb);
+			cb = rx_cbs[pid][qid].cb;
+			if (cb == NULL)
+				continue;
+
+			ret = rte_eth_remove_rx_callback(pid, qid, cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE, "Failed to remove Rx callback");
 		}
+
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
-			cbs = &tx_cbs[pid][qid];
-			ret = rte_eth_remove_tx_callback(pid, qid, cbs->cb);
+			cb = tx_cbs[pid][qid].cb;
+			if (cb == NULL)
+				continue;
+
+			ret = rte_eth_remove_tx_callback(pid, qid, cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE, "Failed to remove Tx callback");
 		}
 	}
 
 	/* free up the memzone */
 	mz = rte_memzone_lookup(MZ_RTE_LATENCY_STATS);
-	if (mz)
-		rte_memzone_free(mz);
+	rte_memzone_free(mz);
 
 	return 0;
 }
@@ -360,6 +383,9 @@ rte_latencystats_get_names(struct rte_metric_name *names, uint16_t size)
 int
 rte_latencystats_get(struct rte_metric_value *values, uint16_t size)
 {
+	unsigned int i;
+	uint64_t stats[NUM_LATENCY_STATS];
+
 	if (size < NUM_LATENCY_STATS || values == NULL)
 		return NUM_LATENCY_STATS;
 
@@ -371,11 +397,18 @@ rte_latencystats_get(struct rte_metric_value *values, uint16_t size)
 				"Latency stats memzone not found");
 			return -ENOMEM;
 		}
-		glob_stats =  mz->addr;
+
+		latency_stats = mz->addr;
 	}
 
 	/* Retrieve latency stats */
-	rte_latencystats_fill_values(values);
+	latencystats_collect(stats);
+
+	for (i = 0; i < NUM_LATENCY_STATS; i++) {
+		values[i].key = i;
+		values[i].value = stats[i];
+	}
+
 
 	return NUM_LATENCY_STATS;
 }
-- 
2.43.0

[PATCH v2] latencystats: performance overhaul

[Stephen Hemminger]

The latencystats library had multiple performance issues.
  - using floating point in the fast path of Tx
  - global lock in fast path
  - global stats cause cache thrashing
  - divide instructions in fast path

Other minor issues:
  - message split across lines
  - error messages not printed with correct priority

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 334 ++++++++++++++++------------
 1 file changed, 187 insertions(+), 147 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 4ea9b0d75b..5154e0650a 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,29 +2,18 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
-#include <math.h>
-
-#include <rte_string_fns.h>
 #include <rte_mbuf_dyn.h>
 #include <rte_log.h>
+#include <rte_stdatomic.h>
 #include <rte_cycles.h>
 #include <rte_ethdev.h>
 #include <rte_metrics.h>
 #include <rte_memzone.h>
 #include <rte_lcore.h>
+#include <rte_time.h>
 
 #include "rte_latencystats.h"
 
-/** Nano seconds per second */
-#define NS_PER_SEC 1E9
-
-/** Clock cycles per nano second */
-static uint64_t
-latencystat_cycles_per_ns(void)
-{
-	return rte_get_timer_hz() / NS_PER_SEC;
-}
-
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
 #define LATENCY_STATS_LOG(level, ...) \
@@ -40,28 +29,32 @@ timestamp_dynfield(struct rte_mbuf *mbuf)
 			timestamp_dynfield_offset, rte_mbuf_timestamp_t *);
 }
 
-static const char *MZ_RTE_LATENCY_STATS = "rte_latencystats";
+static const char MZ_RTE_LATENCY_STATS[] = "rte_latencystats";
 static int latency_stats_index;
 static uint64_t samp_intvl;
-static uint64_t timer_tsc;
-static uint64_t prev_tsc;
 
+/* Per queue latency information (in cycles) */
 struct rte_latency_stats {
-	float min_latency; /**< Minimum latency in nano seconds */
-	float avg_latency; /**< Average latency in nano seconds */
-	float max_latency; /**< Maximum latency in nano seconds */
-	float jitter; /** Latency variation */
-	rte_spinlock_t lock; /** Latency calculation lock */
-};
-
-static struct rte_latency_stats *glob_stats;
-
-struct rxtx_cbs {
+	RTE_ATOMIC(uint64_t) min_latency; /* Minimum latency */
+	RTE_ATOMIC(uint64_t) avg_latency; /* Average latency */
+	RTE_ATOMIC(uint64_t) max_latency; /* Maximum latency */
+	RTE_ATOMIC(uint64_t) jitter;      /* Latency variation */
+} __rte_cache_aligned;
+
+/* per queue info stored in memxone */
+static struct {
+	struct rte_latency_stats stats[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
+} *latency_stats;
+
+static struct {
+	uint64_t prev_tsc;
 	const struct rte_eth_rxtx_callback *cb;
-};
+} rx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 
-static struct rxtx_cbs rx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
-static struct rxtx_cbs tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
+static struct {
+	uint64_t prev_latency;
+	const struct rte_eth_rxtx_callback *cb;
+} tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 
 struct latency_stats_nameoff {
 	char name[RTE_ETH_XSTATS_NAME_SIZE];
@@ -75,51 +68,92 @@ static const struct latency_stats_nameoff lat_stats_strings[] = {
 	{"jitter_ns", offsetof(struct rte_latency_stats, jitter)},
 };
 
-#define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
-				sizeof(lat_stats_strings[0]))
+#define NUM_LATENCY_STATS RTE_DIM(lat_stats_strings)
 
-int32_t
-rte_latencystats_update(void)
+static inline uint64_t
+cycles_to_ns(uint64_t cycles)
 {
-	unsigned int i;
-	float *stats_ptr = NULL;
-	uint64_t values[NUM_LATENCY_STATS] = {0};
-	int ret;
-
-	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i] = (uint64_t)floor((*stats_ptr)/
-				latencystat_cycles_per_ns());
-	}
+	return (cycles * NSEC_PER_SEC) / rte_get_tsc_hz();
+}
 
-	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
-					latency_stats_index,
-					values, NUM_LATENCY_STATS);
-	if (ret < 0)
-		LATENCY_STATS_LOG(INFO, "Failed to push the stats");
+static inline uint64_t
+latencystat_read_ns(__rte_atomic const uint64_t *stat_ptr)
+{
+	return cycles_to_ns(rte_atomic_load_explicit(stat_ptr, rte_memory_order_relaxed));
+}
 
-	return ret;
+static inline void
+latencystat_write(__rte_atomic uint64_t *stat_ptr, uint64_t value)
+{
+	rte_atomic_store_explicit(stat_ptr, value, rte_memory_order_relaxed);
 }
 
+/* aggregate data across all ports and queues */
 static void
-rte_latencystats_fill_values(struct rte_metric_value *values)
+latencystats_collect(uint64_t *values)
 {
-	unsigned int i;
-	float *stats_ptr = NULL;
+	unsigned int i, samples = 0;
+	uint16_t pid, qid;
+	int ret;
+	struct rte_latency_stats sum = { };
+
+	RTE_ETH_FOREACH_DEV(pid) {
+		struct rte_eth_dev_info dev_info;
+
+		ret = rte_eth_dev_info_get(pid, &dev_info);
+		if (ret != 0) {
+			LATENCY_STATS_LOG(ERR,
+				"Error during getting device (port %u) info: %s",
+				pid, strerror(-ret));
+			continue;
+		}
+
+		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
+			const struct rte_latency_stats *stats = &latency_stats->stats[pid][qid];
+			uint64_t l;
+
+			l = latencystat_read_ns(&stats->min_latency);
+			if (l != 0 && (sum.min_latency == 0 || l < sum.min_latency))
+				sum.min_latency = l;
+
+			l = latencystat_read_ns(&stats->max_latency);
+			if (l < sum.max_latency)
+				sum.max_latency = l;
+
+			sum.avg_latency += latencystat_read_ns(&stats->avg_latency);
+			sum.jitter += latencystat_read_ns(&stats->jitter);
+			++samples;
+		}
+
+	}
 
+	/* adjust averages based on number of samples */
+	if (samples > 0) {
+		sum.avg_latency /= samples;
+		sum.jitter /= samples;
+	}
+
+	/* convert cycle counts to ns */
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i].key = i;
-		values[i].value = (uint64_t)floor((*stats_ptr)/
-						latencystat_cycles_per_ns());
+		uint64_t *stats_ptr = RTE_PTR_ADD(&sum, lat_stats_strings[i].offset);
+
+		values[i] = *stats_ptr;
 	}
 }
 
+int32_t
+rte_latencystats_update(void)
+{
+	uint64_t values[NUM_LATENCY_STATS] = { 0 };
+
+	latencystats_collect(values);
+
+	return rte_metrics_update_values(RTE_METRICS_GLOBAL, latency_stats_index,
+					values, NUM_LATENCY_STATS);
+}
+
 static uint16_t
-add_time_stamps(uint16_t pid __rte_unused,
-		uint16_t qid __rte_unused,
+add_time_stamps(uint16_t pid, uint16_t qid,
 		struct rte_mbuf **pkts,
 		uint16_t nb_pkts,
 		uint16_t max_pkts __rte_unused,
@@ -127,55 +161,49 @@ add_time_stamps(uint16_t pid __rte_unused,
 {
 	unsigned int i;
 	uint64_t diff_tsc, now;
+	uint64_t *prev_tsc = &rx_cbs[pid][qid].prev_tsc;
 
 	/*
 	 * For every sample interval,
 	 * time stamp is marked on one received packet.
 	 */
-	now = rte_rdtsc();
 	for (i = 0; i < nb_pkts; i++) {
-		diff_tsc = now - prev_tsc;
-		timer_tsc += diff_tsc;
+		if ((pkts[i]->ol_flags & timestamp_dynflag) != 0)
+			continue;
 
-		if ((pkts[i]->ol_flags & timestamp_dynflag) == 0
-				&& (timer_tsc >= samp_intvl)) {
+		now = rte_rdtsc();
+		diff_tsc = now - *prev_tsc;
+		if (diff_tsc >= samp_intvl) {
 			*timestamp_dynfield(pkts[i]) = now;
 			pkts[i]->ol_flags |= timestamp_dynflag;
-			timer_tsc = 0;
+			*prev_tsc = now;
+			break;
 		}
-		prev_tsc = now;
-		now = rte_rdtsc();
 	}
 
 	return nb_pkts;
 }
 
 static uint16_t
-calc_latency(uint16_t pid __rte_unused,
-		uint16_t qid __rte_unused,
-		struct rte_mbuf **pkts,
-		uint16_t nb_pkts,
-		void *_ __rte_unused)
+calc_latency(uint16_t pid, uint16_t qid,
+	     struct rte_mbuf **pkts, uint16_t nb_pkts,
+	     void *user_cb __rte_unused)
 {
-	unsigned int i, cnt = 0;
-	uint64_t now;
-	float latency[nb_pkts];
-	static float prev_latency;
-	/*
-	 * Alpha represents degree of weighting decrease in EWMA,
-	 * a constant smoothing factor between 0 and 1. The value
-	 * is used below for measuring average latency.
-	 */
-	const float alpha = 0.2;
+	struct rte_latency_stats *stats = &latency_stats->stats[pid][qid];
+	unsigned int i;
+	uint64_t now, *prev_latency;
 
+	prev_latency = &tx_cbs[pid][qid].prev_latency;
 	now = rte_rdtsc();
 	for (i = 0; i < nb_pkts; i++) {
-		if (pkts[i]->ol_flags & timestamp_dynflag)
-			latency[cnt++] = now - *timestamp_dynfield(pkts[i]);
-	}
+		uint64_t latency;
+		int64_t delta;
+
+		if ((pkts[i]->ol_flags & timestamp_dynflag) == 0)
+			continue;
+
+		latency = now - *timestamp_dynfield(pkts[i]);
 
-	rte_spinlock_lock(&glob_stats->lock);
-	for (i = 0; i < cnt; i++) {
 		/*
 		 * The jitter is calculated as statistical mean of interpacket
 		 * delay variation. The "jitter estimate" is computed by taking
@@ -187,24 +215,25 @@ calc_latency(uint16_t pid __rte_unused,
 		 * Reference: Calculated as per RFC 5481, sec 4.1,
 		 * RFC 3393 sec 4.5, RFC 1889 sec.
 		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency[i])
-					- glob_stats->jitter)/16;
-		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] < glob_stats->min_latency)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] > glob_stats->max_latency)
-			glob_stats->max_latency = latency[i];
+		delta = *prev_latency - latency;
+		*prev_latency = latency;
+		latencystat_write(&stats->jitter,
+				  stats->jitter + (delta - stats->jitter) / 16);
+
+		if (stats->min_latency == 0 || latency < stats->min_latency)
+			latencystat_write(&stats->min_latency, latency);
+		else if (latency > stats->max_latency)
+			latencystat_write(&stats->max_latency, latency);
+
 		/*
 		 * The average latency is measured using exponential moving
 		 * average, i.e. using EWMA
 		 * https://en.wikipedia.org/wiki/Moving_average
 		 */
-		glob_stats->avg_latency +=
-			alpha * (latency[i] - glob_stats->avg_latency);
-		prev_latency = latency[i];
+		delta = latency - stats->avg_latency;
+		latency = (delta + 3 * stats->avg_latency) / 4;
+		latencystat_write(&stats->avg_latency, latency);
 	}
-	rte_spinlock_unlock(&glob_stats->lock);
 
 	return nb_pkts;
 }
@@ -214,38 +243,34 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		rte_latency_stats_flow_type_fn user_cb)
 {
 	unsigned int i;
-	uint16_t pid;
-	uint16_t qid;
-	struct rxtx_cbs *cbs = NULL;
-	const char *ptr_strings[NUM_LATENCY_STATS] = {0};
-	const struct rte_memzone *mz = NULL;
-	const unsigned int flags = 0;
+	uint16_t pid, qid;
+	const char *ptr_strings[NUM_LATENCY_STATS];
+	const struct rte_memzone *mz;
 	int ret;
 
 	if (rte_memzone_lookup(MZ_RTE_LATENCY_STATS))
 		return -EEXIST;
 
-	/** Allocate stats in shared memory fo multi process support */
-	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*glob_stats),
-					rte_socket_id(), flags);
+	/** Allocate stats in shared memory for multi process support */
+	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*latency_stats),
+					rte_socket_id(), 0);
 	if (mz == NULL) {
 		LATENCY_STATS_LOG(ERR, "Cannot reserve memory: %s:%d",
 			__func__, __LINE__);
 		return -ENOMEM;
 	}
 
-	glob_stats = mz->addr;
-	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	latency_stats = mz->addr;
+	samp_intvl = (app_samp_intvl * NSEC_PER_SEC) / rte_get_tsc_hz();
 
-	/** Register latency stats with stats library */
+	/* Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
 		ptr_strings[i] = lat_stats_strings[i].name;
 
 	latency_stats_index = rte_metrics_reg_names(ptr_strings,
 							NUM_LATENCY_STATS);
 	if (latency_stats_index < 0) {
-		LATENCY_STATS_LOG(DEBUG,
+		LATENCY_STATS_LOG(ERR,
 			"Failed to register latency stats names");
 		return -1;
 	}
@@ -262,10 +287,11 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	/** Register Rx/Tx callbacks */
 	RTE_ETH_FOREACH_DEV(pid) {
 		struct rte_eth_dev_info dev_info;
+		const struct rte_eth_rxtx_callback *cb;
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -273,23 +299,25 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		}
 
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
-			cbs = &rx_cbs[pid][qid];
-			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
-					add_time_stamps, user_cb);
-			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+			cb = rte_eth_add_first_rx_callback(pid, qid, add_time_stamps, user_cb);
+			if (cb)
+				rx_cbs[pid][qid].cb = cb;
+			else
+				LATENCY_STATS_LOG(NOTICE,
+						  "Failed to register Rx callback for pid=%d, qid=%d",
+						  pid, qid);
 		}
+
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
-			cbs = &tx_cbs[pid][qid];
-			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
-					calc_latency, user_cb);
-			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+			cb = rte_eth_add_tx_callback(pid, qid, calc_latency, user_cb);
+			if (cb)
+				tx_cbs[pid][qid].cb = cb;
+			else
+				LATENCY_STATS_LOG(NOTICE,
+						  "Failed to register Tx callback for pid=%d, qid=%d",
+						  pid, qid);
 		}
+
 	}
 	return 0;
 }
@@ -297,19 +325,18 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 int
 rte_latencystats_uninit(void)
 {
-	uint16_t pid;
-	uint16_t qid;
-	int ret = 0;
-	struct rxtx_cbs *cbs = NULL;
-	const struct rte_memzone *mz = NULL;
+	const struct rte_memzone *mz;
+	uint16_t pid, qid;
+	int ret;
 
 	/** De register Rx/Tx callbacks */
 	RTE_ETH_FOREACH_DEV(pid) {
 		struct rte_eth_dev_info dev_info;
+		const struct rte_eth_rxtx_callback *cb;
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -317,20 +344,23 @@ rte_latencystats_uninit(void)
 		}
 
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
-			cbs = &rx_cbs[pid][qid];
-			ret = rte_eth_remove_rx_callback(pid, qid, cbs->cb);
+			cb = rx_cbs[pid][qid].cb;
+			if (cb == NULL)
+				continue;
+
+			ret = rte_eth_remove_rx_callback(pid, qid, cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE, "Failed to remove Rx callback");
 		}
+
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
-			cbs = &tx_cbs[pid][qid];
-			ret = rte_eth_remove_tx_callback(pid, qid, cbs->cb);
+			cb = tx_cbs[pid][qid].cb;
+			if (cb == NULL)
+				continue;
+
+			ret = rte_eth_remove_tx_callback(pid, qid, cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE, "Failed to remove Tx callback");
 		}
 	}
 
@@ -360,6 +390,9 @@ rte_latencystats_get_names(struct rte_metric_name *names, uint16_t size)
 int
 rte_latencystats_get(struct rte_metric_value *values, uint16_t size)
 {
+	unsigned int i;
+	uint64_t stats[NUM_LATENCY_STATS];
+
 	if (size < NUM_LATENCY_STATS || values == NULL)
 		return NUM_LATENCY_STATS;
 
@@ -371,11 +404,18 @@ rte_latencystats_get(struct rte_metric_value *values, uint16_t size)
 				"Latency stats memzone not found");
 			return -ENOMEM;
 		}
-		glob_stats =  mz->addr;
+
+		latency_stats = mz->addr;
 	}
 
 	/* Retrieve latency stats */
-	rte_latencystats_fill_values(values);
+	latencystats_collect(stats);
+
+	for (i = 0; i < NUM_LATENCY_STATS; i++) {
+		values[i].key = i;
+		values[i].value = stats[i];
+	}
+
 
 	return NUM_LATENCY_STATS;
 }
-- 
2.43.0

[PATCH v4 0/6] latencystats: cleanup

[Stephen Hemminger]

Latencystats uses variable length array and floating point when they
are not necessary to acheive the same result. While testing also noticed
that the code was computing wrong values on my test system, and that
include files were missing.

v4 - review feedback and fix pedantic warnings

Stephen Hemminger (6):
  latencystats: replace use of VLA
  latencystats: handle fractional cycles per ns
  latencystats: do not use floating point
  latencystats: fix log messages
  latencystats: update include files
  latencystats: fix for pedantic warnings

 lib/latencystats/rte_latencystats.c | 182 +++++++++++++++-------------
 1 file changed, 96 insertions(+), 86 deletions(-)

-- 
2.43.0

[PATCH v4 1/6] latencystats: replace use of VLA

[Stephen Hemminger]

The temporary array latencystats is not needed if the algorithm
is converted into one pass.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 31 +++++++++++++++--------------
 1 file changed, 16 insertions(+), 15 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 4ea9b0d75b..9b345bfb33 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -157,9 +157,9 @@ calc_latency(uint16_t pid __rte_unused,
 		uint16_t nb_pkts,
 		void *_ __rte_unused)
 {
-	unsigned int i, cnt = 0;
+	unsigned int i;
 	uint64_t now;
-	float latency[nb_pkts];
+	float latency;
 	static float prev_latency;
 	/*
 	 * Alpha represents degree of weighting decrease in EWMA,
@@ -169,13 +169,14 @@ calc_latency(uint16_t pid __rte_unused,
 	const float alpha = 0.2;
 
 	now = rte_rdtsc();
-	for (i = 0; i < nb_pkts; i++) {
-		if (pkts[i]->ol_flags & timestamp_dynflag)
-			latency[cnt++] = now - *timestamp_dynfield(pkts[i]);
-	}
 
 	rte_spinlock_lock(&glob_stats->lock);
-	for (i = 0; i < cnt; i++) {
+	for (i = 0; i < nb_pkts; i++) {
+		if (!(pkts[i]->ol_flags & timestamp_dynflag))
+			continue;
+
+		latency = now - *timestamp_dynfield(pkts[i]);
+
 		/*
 		 * The jitter is calculated as statistical mean of interpacket
 		 * delay variation. The "jitter estimate" is computed by taking
@@ -187,22 +188,22 @@ calc_latency(uint16_t pid __rte_unused,
 		 * Reference: Calculated as per RFC 5481, sec 4.1,
 		 * RFC 3393 sec 4.5, RFC 1889 sec.
 		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency[i])
+		glob_stats->jitter +=  (fabsf(prev_latency - latency)
 					- glob_stats->jitter)/16;
 		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] < glob_stats->min_latency)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] > glob_stats->max_latency)
-			glob_stats->max_latency = latency[i];
+			glob_stats->min_latency = latency;
+		else if (latency < glob_stats->min_latency)
+			glob_stats->min_latency = latency;
+		else if (latency > glob_stats->max_latency)
+			glob_stats->max_latency = latency;
 		/*
 		 * The average latency is measured using exponential moving
 		 * average, i.e. using EWMA
 		 * https://en.wikipedia.org/wiki/Moving_average
 		 */
 		glob_stats->avg_latency +=
-			alpha * (latency[i] - glob_stats->avg_latency);
-		prev_latency = latency[i];
+			alpha * (latency - glob_stats->avg_latency);
+		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
 
-- 
2.43.0

[PATCH v4 2/6] latencystats: handle fractional cycles per ns

[Stephen Hemminger]

The timer_hz is not always an integral number of nanoseconds.
For examples, cycles per nanoseconds on my test system is 2.8.
Fix by using floating point where needed and calculate value once.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 9b345bfb33..55a099c818 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -18,12 +18,7 @@
 /** Nano seconds per second */
 #define NS_PER_SEC 1E9
 
-/** Clock cycles per nano second */
-static uint64_t
-latencystat_cycles_per_ns(void)
-{
-	return rte_get_timer_hz() / NS_PER_SEC;
-}
+static double cycles_per_ns;
 
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
@@ -89,8 +84,7 @@ rte_latencystats_update(void)
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
-		values[i] = (uint64_t)floor((*stats_ptr)/
-				latencystat_cycles_per_ns());
+		values[i] = floor(*stats_ptr / cycles_per_ns);
 	}
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
@@ -112,8 +106,7 @@ rte_latencystats_fill_values(struct rte_metric_value *values)
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
 		values[i].key = i;
-		values[i].value = (uint64_t)floor((*stats_ptr)/
-						latencystat_cycles_per_ns());
+		values[i].value = floor(*stats_ptr / cycles_per_ns);
 	}
 }
 
@@ -235,9 +228,11 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		return -ENOMEM;
 	}
 
+	cycles_per_ns = (double)rte_get_timer_hz() / NS_PER_SEC;
+
 	glob_stats = mz->addr;
 	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	samp_intvl = (uint64_t)(app_samp_intvl * cycles_per_ns);
 
 	/** Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
-- 
2.43.0

[PATCH v4 3/6] latencystats: do not use floating point

[Stephen Hemminger]

The cycle counts do not need to be stored as floating point.
Instead keep track of latency in cycles, and convert to
nanoseconds when read.

Change Exponential Weighted Moving Average weight from .2 to .25
to avoid use of floating point for that.

The average latency took too long to "warm up".
Do what RFC 6298 suggests and initialize on first sample.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 88 +++++++++++++++--------------
 1 file changed, 45 insertions(+), 43 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 55a099c818..6ef8e344bf 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -4,6 +4,7 @@
 
 #include <math.h>
 
+#include <rte_common.h>
 #include <rte_string_fns.h>
 #include <rte_mbuf_dyn.h>
 #include <rte_log.h>
@@ -42,10 +43,10 @@ static uint64_t timer_tsc;
 static uint64_t prev_tsc;
 
 struct rte_latency_stats {
-	float min_latency; /**< Minimum latency in nano seconds */
-	float avg_latency; /**< Average latency in nano seconds */
-	float max_latency; /**< Maximum latency in nano seconds */
-	float jitter; /** Latency variation */
+	uint64_t min_latency; /**< Minimum latency */
+	uint64_t avg_latency; /**< Average latency */
+	uint64_t max_latency; /**< Maximum latency */
+	uint64_t jitter; /** Latency variation */
 	rte_spinlock_t lock; /** Latency calculation lock */
 };
 
@@ -77,13 +78,12 @@ int32_t
 rte_latencystats_update(void)
 {
 	unsigned int i;
-	float *stats_ptr = NULL;
 	uint64_t values[NUM_LATENCY_STATS] = {0};
 	int ret;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
+		const uint64_t *stats_ptr
+			= RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
 		values[i] = floor(*stats_ptr / cycles_per_ns);
 	}
 
@@ -100,11 +100,10 @@ static void
 rte_latencystats_fill_values(struct rte_metric_value *values)
 {
 	unsigned int i;
-	float *stats_ptr = NULL;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
+		const uint64_t *stats_ptr
+			= RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
 		values[i].key = i;
 		values[i].value = floor(*stats_ptr / cycles_per_ns);
 	}
@@ -151,15 +150,9 @@ calc_latency(uint16_t pid __rte_unused,
 		void *_ __rte_unused)
 {
 	unsigned int i;
-	uint64_t now;
-	float latency;
-	static float prev_latency;
-	/*
-	 * Alpha represents degree of weighting decrease in EWMA,
-	 * a constant smoothing factor between 0 and 1. The value
-	 * is used below for measuring average latency.
-	 */
-	const float alpha = 0.2;
+	uint64_t now, latency;
+	static uint64_t prev_latency;
+	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -170,32 +163,41 @@ calc_latency(uint16_t pid __rte_unused,
 
 		latency = now - *timestamp_dynfield(pkts[i]);
 
-		/*
-		 * The jitter is calculated as statistical mean of interpacket
-		 * delay variation. The "jitter estimate" is computed by taking
-		 * the absolute values of the ipdv sequence and applying an
-		 * exponential filter with parameter 1/16 to generate the
-		 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
-		 * D(i-1,i) is difference in latency of two consecutive packets
-		 * i-1 and i.
-		 * Reference: Calculated as per RFC 5481, sec 4.1,
-		 * RFC 3393 sec 4.5, RFC 1889 sec.
-		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency)
-					- glob_stats->jitter)/16;
-		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency;
-		else if (latency < glob_stats->min_latency)
+		if (unlikely(first_sample)) {
+			first_sample = false;
+
 			glob_stats->min_latency = latency;
-		else if (latency > glob_stats->max_latency)
 			glob_stats->max_latency = latency;
-		/*
-		 * The average latency is measured using exponential moving
-		 * average, i.e. using EWMA
-		 * https://en.wikipedia.org/wiki/Moving_average
-		 */
-		glob_stats->avg_latency +=
-			alpha * (latency - glob_stats->avg_latency);
+			glob_stats->avg_latency = latency;
+			glob_stats->jitter = latency / 2;
+		} else {
+			/*
+			 * The jitter is calculated as statistical mean of interpacket
+			 * delay variation. The "jitter estimate" is computed by taking
+			 * the absolute values of the ipdv sequence and applying an
+			 * exponential filter with parameter 1/16 to generate the
+			 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
+			 * D(i-1,i) is difference in latency of two consecutive packets
+			 * i-1 and i.
+			 * Reference: Calculated as per RFC 5481, sec 4.1,
+			 * RFC 3393 sec 4.5, RFC 1889 sec.
+			 */
+			glob_stats->jitter += ((prev_latency - latency)
+					       - glob_stats->jitter) / 16;
+			if (latency < glob_stats->min_latency)
+				glob_stats->min_latency = latency;
+			if (latency > glob_stats->max_latency)
+				glob_stats->max_latency = latency;
+			/*
+			 * The average latency is measured using exponential moving
+			 * average, i.e. using EWMA
+			 * https://en.wikipedia.org/wiki/Moving_average
+			 *
+			 * Alpha is .25
+			 */
+			glob_stats->avg_latency += (latency - glob_stats->avg_latency) / 4;
+		}
+
 		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
-- 
2.43.0

RE: [PATCH v4 3/6] latencystats: do not use floating point

[Morten Brørup]

> +		if (unlikely(first_sample)) {
> +			first_sample = false;
> +
>  			glob_stats->min_latency = latency;
> -		else if (latency > glob_stats->max_latency)
>  			glob_stats->max_latency = latency;
> -		/*
> -		 * The average latency is measured using exponential moving
> -		 * average, i.e. using EWMA
> -		 * https://en.wikipedia.org/wiki/Moving_average
> -		 */
> -		glob_stats->avg_latency +=
> -			alpha * (latency - glob_stats->avg_latency);
> +			glob_stats->avg_latency = latency;
> +			glob_stats->jitter = latency / 2;

Setting jitter at first sample as latency / 2 is wrong.
Jitter should remain zero at first sample.

> +		} else {
> +			/*
> +			 * The jitter is calculated as statistical mean of
> interpacket
> +			 * delay variation. The "jitter estimate" is computed
> by taking
> +			 * the absolute values of the ipdv sequence and
> applying an
> +			 * exponential filter with parameter 1/16 to generate
> the
> +			 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is
> jitter,
> +			 * D(i-1,i) is difference in latency of two
> consecutive packets
> +			 * i-1 and i.
> +			 * Reference: Calculated as per RFC 5481, sec 4.1,
> +			 * RFC 3393 sec 4.5, RFC 1889 sec.
> +			 */
> +			glob_stats->jitter += ((prev_latency - latency)
> +					       - glob_stats->jitter) / 16;

With jitter remaining zero at first sample,
Acked-by: Morten Brørup <mb@smartsharesystems.com>

Re: [PATCH v4 3/6] latencystats: do not use floating point

[Stephen Hemminger]

On Fri, 19 Apr 2024 20:49:56 +0200
Morten Brørup <mb@smartsharesystems.com> wrote:

> > -		/*
> > -		 * The average latency is measured using exponential moving
> > -		 * average, i.e. using EWMA
> > -		 * https://en.wikipedia.org/wiki/Moving_average
> > -		 */
> > -		glob_stats->avg_latency +=
> > -			alpha * (latency - glob_stats->avg_latency);
> > +			glob_stats->avg_latency = latency;
> > +			glob_stats->jitter = latency / 2;  
> 
> Setting jitter at first sample as latency / 2 is wrong.
> Jitter should remain zero at first sample.

Chose that because it is what the TCP RFC does.
RFC 6298
	
   (2.2) When the first RTT measurement R is made, the host MUST set

            SRTT <- R
            RTTVAR <- R/2
            RTO <- SRTT + max (G, K*RTTVAR)

The problem is that the smoothing constant in this code is quite small.
Also, the TCP RFC has, not sure if matters.

   (2.3) When a subsequent RTT measurement R' is made, a host MUST set

            RTTVAR <- (1 - beta) * RTTVAR + beta * |SRTT - R'|
            SRTT <- (1 - alpha) * SRTT + alpha * R'

         The value of SRTT used in the update to RTTVAR is its value
         before updating SRTT itself using the second assignment.  That
         is, updating RTTVAR and SRTT MUST be computed in the above
         order.

         The above SHOULD be computed using alpha=1/8 and beta=1/4 (as
         suggested in [JK88]).

         After the computation, a host MUST update
         RTO <- SRTT + max (G, K*RTTVAR)

RE: [PATCH v4 3/6] latencystats: do not use floating point

[Morten Brørup]

> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Saturday, 20 April 2024 00.45
> 
> On Fri, 19 Apr 2024 20:49:56 +0200
> Morten Brørup <mb@smartsharesystems.com> wrote:
> 
> > > -		/*
> > > -		 * The average latency is measured using exponential moving
> > > -		 * average, i.e. using EWMA
> > > -		 * https://en.wikipedia.org/wiki/Moving_average
> > > -		 */
> > > -		glob_stats->avg_latency +=
> > > -			alpha * (latency - glob_stats->avg_latency);
> > > +			glob_stats->avg_latency = latency;
> > > +			glob_stats->jitter = latency / 2;
> >
> > Setting jitter at first sample as latency / 2 is wrong.
> > Jitter should remain zero at first sample.
> 
> Chose that because it is what the TCP RFC does.

I suppose it depends on what the measured jitter is being used for.

<rant>
1/2 is very far from the predominant Jitter/RTT relationship I usually see on internet connections.
Jitter is mostly in the ~2 ms order of magnitude, while RTT may be anything between 10 and 600 ms.
Although some links may experience much higher jitter under load, the RTT usually also increases to 100's of milliseconds under these conditions.
Some people are on a crusade to combat this "latency under load" bufferbloat phenomenon. The path towards achieving this begins with measuring and educating.
</rant>

Your RFC reference is a very strong argument.
If the measured jitter is used as a measure of uncertainty in the measured RTT, it makes sense starting high.
I'll accept it.

Acked-by: Morten Brørup <mb@smartsharesystems.com>

> RFC 6298
> 
>    (2.2) When the first RTT measurement R is made, the host MUST set
> 
>             SRTT <- R
>             RTTVAR <- R/2
>             RTO <- SRTT + max (G, K*RTTVAR)
> 
> The problem is that the smoothing constant in this code is quite small.
> Also, the TCP RFC has, not sure if matters.
> 
>    (2.3) When a subsequent RTT measurement R' is made, a host MUST set
> 
>             RTTVAR <- (1 - beta) * RTTVAR + beta * |SRTT - R'|
>             SRTT <- (1 - alpha) * SRTT + alpha * R'
> 
>          The value of SRTT used in the update to RTTVAR is its value
>          before updating SRTT itself using the second assignment.  That
>          is, updating RTTVAR and SRTT MUST be computed in the above
>          order.
> 
>          The above SHOULD be computed using alpha=1/8 and beta=1/4 (as
>          suggested in [JK88]).
> 
>          After the computation, a host MUST update
>          RTO <- SRTT + max (G, K*RTTVAR)

[PATCH v4 4/6] latencystats: fix log messages

[Stephen Hemminger]

All messages that because of an error should be at log level
NOTICE or above. Do not break log messages across lines.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 30 ++++++++++++++---------------
 1 file changed, 15 insertions(+), 15 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 6ef8e344bf..8aff96a449 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -243,7 +243,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	latency_stats_index = rte_metrics_reg_names(ptr_strings,
 							NUM_LATENCY_STATS);
 	if (latency_stats_index < 0) {
-		LATENCY_STATS_LOG(DEBUG,
+		LATENCY_STATS_LOG(ERR,
 			"Failed to register latency stats names");
 		return -1;
 	}
@@ -263,7 +263,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -275,18 +275,18 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
 					add_time_stamps, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
 					calc_latency, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 	return 0;
@@ -307,7 +307,7 @@ rte_latencystats_uninit(void)
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
+			LATENCY_STATS_LOG(NOTICE,
 				"Error during getting device (port %u) info: %s",
 				pid, strerror(-ret));
 
@@ -318,17 +318,17 @@ rte_latencystats_uninit(void)
 			cbs = &rx_cbs[pid][qid];
 			ret = rte_eth_remove_rx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			ret = rte_eth_remove_tx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 
-- 
2.43.0

[PATCH v4 5/6] latencystats: update include files

[Stephen Hemminger]

Include what is used here.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 8aff96a449..5db896ac7b 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,17 +2,25 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
+#include <errno.h>
 #include <math.h>
+#include <stdbool.h>
+#include <stddef.h>
+#include <string.h>
 
 #include <rte_common.h>
-#include <rte_string_fns.h>
-#include <rte_mbuf_dyn.h>
-#include <rte_log.h>
 #include <rte_cycles.h>
+#include <rte_eal.h>
+#include <rte_errno.h>
 #include <rte_ethdev.h>
-#include <rte_metrics.h>
-#include <rte_memzone.h>
 #include <rte_lcore.h>
+#include <rte_log.h>
+#include <rte_mbuf.h>
+#include <rte_mbuf_dyn.h>
+#include <rte_memzone.h>
+#include <rte_metrics.h>
+#include <rte_spinlock.h>
+#include <rte_string_fns.h>
 
 #include "rte_latencystats.h"
 
-- 
2.43.0

[PATCH v4 6/6] latencystats: fix for pedantic warnings

[Stephen Hemminger]

ISO C does not allow casting function pointer to void *.
Resolve by enforcing the reserved argument.
The user_cb argument for rte_latencystats_init() was not
implemented, and had to be NULL anyway.

The log type is local to this function and RTE_LOG_REGISTER_DEFAULT
alread has a semicolon. So adding one here causes a warning
if compiler is set to pedantic.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 5db896ac7b..f60c893199 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -29,7 +29,7 @@
 
 static double cycles_per_ns;
 
-RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
+static RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO)
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
 #define LATENCY_STATS_LOG(level, ...) \
 	RTE_LOG_LINE(level, LATENCY_STATS, "" __VA_ARGS__)
@@ -229,6 +229,10 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	if (rte_memzone_lookup(MZ_RTE_LATENCY_STATS))
 		return -EEXIST;
 
+	/** Reserved for possible future use */
+	if (user_cb != NULL)
+		return -ENOTSUP;
+
 	/** Allocate stats in shared memory fo multi process support */
 	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*glob_stats),
 					rte_socket_id(), flags);
@@ -281,7 +285,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
 			cbs = &rx_cbs[pid][qid];
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
-					add_time_stamps, user_cb);
+					add_time_stamps, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Rx callback for pid=%u, qid=%u",
@@ -290,7 +294,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
-					calc_latency, user_cb);
+					calc_latency, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Tx callback for pid=%u, qid=%u",
-- 
2.43.0

[PATCH v5 0/9] latencystats: improve algorithms and tests

[Stephen Hemminger]

Latencystats uses variable length array and floating point when they
are not necessary to acheive the same result. While testing also noticed
that the code was computing wrong values on my test system, and that
include files were missing.

v5 - use scaled values for latency and jitter
   - add more test cases
   - review feedback

Stephen Hemminger (9):
  latencystats: replace use of VLA
  latencystats: handle fractional cycles per ns
  latencystats: do not use floating point
  latencystats: fix log messages
  latencystats: update include files
  latencystats: enforce that unused callback function is NULL
  latencystats: add metric for number of samples
  test: use initialization in latencystats test
  test: add more latencystats tests

 app/test/test_latencystats.c        |  84 ++++++----
 lib/latencystats/rte_latencystats.c | 232 ++++++++++++++++------------
 2 files changed, 188 insertions(+), 128 deletions(-)

-- 
2.43.0

[PATCH v5 1/9] latencystats: replace use of VLA

[Stephen Hemminger]

The temporary array latencystats is not needed if the algorithm
is converted into one pass.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 31 +++++++++++++++--------------
 1 file changed, 16 insertions(+), 15 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 4ea9b0d75b..9b345bfb33 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -157,9 +157,9 @@ calc_latency(uint16_t pid __rte_unused,
 		uint16_t nb_pkts,
 		void *_ __rte_unused)
 {
-	unsigned int i, cnt = 0;
+	unsigned int i;
 	uint64_t now;
-	float latency[nb_pkts];
+	float latency;
 	static float prev_latency;
 	/*
 	 * Alpha represents degree of weighting decrease in EWMA,
@@ -169,13 +169,14 @@ calc_latency(uint16_t pid __rte_unused,
 	const float alpha = 0.2;
 
 	now = rte_rdtsc();
-	for (i = 0; i < nb_pkts; i++) {
-		if (pkts[i]->ol_flags & timestamp_dynflag)
-			latency[cnt++] = now - *timestamp_dynfield(pkts[i]);
-	}
 
 	rte_spinlock_lock(&glob_stats->lock);
-	for (i = 0; i < cnt; i++) {
+	for (i = 0; i < nb_pkts; i++) {
+		if (!(pkts[i]->ol_flags & timestamp_dynflag))
+			continue;
+
+		latency = now - *timestamp_dynfield(pkts[i]);
+
 		/*
 		 * The jitter is calculated as statistical mean of interpacket
 		 * delay variation. The "jitter estimate" is computed by taking
@@ -187,22 +188,22 @@ calc_latency(uint16_t pid __rte_unused,
 		 * Reference: Calculated as per RFC 5481, sec 4.1,
 		 * RFC 3393 sec 4.5, RFC 1889 sec.
 		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency[i])
+		glob_stats->jitter +=  (fabsf(prev_latency - latency)
 					- glob_stats->jitter)/16;
 		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] < glob_stats->min_latency)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] > glob_stats->max_latency)
-			glob_stats->max_latency = latency[i];
+			glob_stats->min_latency = latency;
+		else if (latency < glob_stats->min_latency)
+			glob_stats->min_latency = latency;
+		else if (latency > glob_stats->max_latency)
+			glob_stats->max_latency = latency;
 		/*
 		 * The average latency is measured using exponential moving
 		 * average, i.e. using EWMA
 		 * https://en.wikipedia.org/wiki/Moving_average
 		 */
 		glob_stats->avg_latency +=
-			alpha * (latency[i] - glob_stats->avg_latency);
-		prev_latency = latency[i];
+			alpha * (latency - glob_stats->avg_latency);
+		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
 
-- 
2.43.0

[PATCH v5 2/9] latencystats: handle fractional cycles per ns

[Stephen Hemminger]

The TSC frequency is not always an integral number of nanoseconds.
For examples, cycles per nanoseconds on my test system is 2.8.
Fix by using floating point where needed and calculate value once.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 9b345bfb33..3152256066 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -18,12 +18,7 @@
 /** Nano seconds per second */
 #define NS_PER_SEC 1E9
 
-/** Clock cycles per nano second */
-static uint64_t
-latencystat_cycles_per_ns(void)
-{
-	return rte_get_timer_hz() / NS_PER_SEC;
-}
+static double cycles_per_ns;
 
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
@@ -89,8 +84,7 @@ rte_latencystats_update(void)
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
-		values[i] = (uint64_t)floor((*stats_ptr)/
-				latencystat_cycles_per_ns());
+		values[i] = floor(*stats_ptr / cycles_per_ns);
 	}
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
@@ -112,8 +106,7 @@ rte_latencystats_fill_values(struct rte_metric_value *values)
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
 		values[i].key = i;
-		values[i].value = (uint64_t)floor((*stats_ptr)/
-						latencystat_cycles_per_ns());
+		values[i].value = floor(*stats_ptr / cycles_per_ns);
 	}
 }
 
@@ -235,9 +228,11 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		return -ENOMEM;
 	}
 
+	cycles_per_ns = (double)rte_get_tsc_hz() / NS_PER_SEC;
+
 	glob_stats = mz->addr;
 	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	samp_intvl = (uint64_t)(app_samp_intvl * cycles_per_ns);
 
 	/** Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
-- 
2.43.0

[PATCH v5 3/9] latencystats: do not use floating point

[Stephen Hemminger]

The cycle counts do not need to be stored as floating point.
Instead keep track of latency in cycles, and convert to
nanoseconds when read.

Use scaled math with exponential Weighted Moving Average weight
of .25 to avoid use of floating point for that.

The average latency took too long to "warm up".
Do what RFC 6298 suggests and initialize on first sample.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
---
 lib/latencystats/rte_latencystats.c | 128 ++++++++++++++++------------
 1 file changed, 73 insertions(+), 55 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 3152256066..2140ab87c4 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -4,6 +4,7 @@
 
 #include <math.h>
 
+#include <rte_common.h>
 #include <rte_string_fns.h>
 #include <rte_mbuf_dyn.h>
 #include <rte_log.h>
@@ -41,11 +42,14 @@ static uint64_t samp_intvl;
 static uint64_t timer_tsc;
 static uint64_t prev_tsc;
 
+#define LATENCY_AVG_SCALE     4
+#define LATENCY_JITTER_SCALE 16
+
 struct rte_latency_stats {
-	float min_latency; /**< Minimum latency in nano seconds */
-	float avg_latency; /**< Average latency in nano seconds */
-	float max_latency; /**< Maximum latency in nano seconds */
-	float jitter; /** Latency variation */
+	uint64_t min_latency; /**< Minimum latency */
+	uint64_t avg_latency; /**< Average latency */
+	uint64_t max_latency; /**< Maximum latency */
+	uint64_t jitter; /** Latency variation */
 	rte_spinlock_t lock; /** Latency calculation lock */
 };
 
@@ -61,31 +65,38 @@ static struct rxtx_cbs tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 struct latency_stats_nameoff {
 	char name[RTE_ETH_XSTATS_NAME_SIZE];
 	unsigned int offset;
+	unsigned int scale;
 };
 
 static const struct latency_stats_nameoff lat_stats_strings[] = {
-	{"min_latency_ns", offsetof(struct rte_latency_stats, min_latency)},
-	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency)},
-	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency)},
-	{"jitter_ns", offsetof(struct rte_latency_stats, jitter)},
+	{"min_latency_ns", offsetof(struct rte_latency_stats, min_latency), 1},
+	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency), LATENCY_AVG_SCALE},
+	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency), 1},
+	{"jitter_ns", offsetof(struct rte_latency_stats, jitter), LATENCY_JITTER_SCALE},
 };
 
 #define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
 				sizeof(lat_stats_strings[0]))
 
-int32_t
-rte_latencystats_update(void)
+static void
+latencystats_collect(uint64_t values[])
 {
 	unsigned int i;
-	float *stats_ptr = NULL;
-	uint64_t values[NUM_LATENCY_STATS] = {0};
-	int ret;
+	const uint64_t *stats;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i] = floor(*stats_ptr / cycles_per_ns);
+		stats = RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
+		values[i] = floor(*stats / (cycles_per_ns * lat_stats_strings[i].scale));
 	}
+}
+
+int32_t
+rte_latencystats_update(void)
+{
+	uint64_t values[NUM_LATENCY_STATS];
+	int ret;
+
+	latencystats_collect(values);
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
 					latency_stats_index,
@@ -97,16 +108,16 @@ rte_latencystats_update(void)
 }
 
 static void
-rte_latencystats_fill_values(struct rte_metric_value *values)
+rte_latencystats_fill_values(struct rte_metric_value *metrics)
 {
+	uint64_t values[NUM_LATENCY_STATS];
 	unsigned int i;
-	float *stats_ptr = NULL;
+
+	latencystats_collect(values);
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i].key = i;
-		values[i].value = floor(*stats_ptr / cycles_per_ns);
+		metrics[i].key = i;
+		metrics[i].value = values[i];
 	}
 }
 
@@ -151,15 +162,9 @@ calc_latency(uint16_t pid __rte_unused,
 		void *_ __rte_unused)
 {
 	unsigned int i;
-	uint64_t now;
-	float latency;
-	static float prev_latency;
-	/*
-	 * Alpha represents degree of weighting decrease in EWMA,
-	 * a constant smoothing factor between 0 and 1. The value
-	 * is used below for measuring average latency.
-	 */
-	const float alpha = 0.2;
+	uint64_t now, latency;
+	static uint64_t prev_latency;
+	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -170,32 +175,45 @@ calc_latency(uint16_t pid __rte_unused,
 
 		latency = now - *timestamp_dynfield(pkts[i]);
 
-		/*
-		 * The jitter is calculated as statistical mean of interpacket
-		 * delay variation. The "jitter estimate" is computed by taking
-		 * the absolute values of the ipdv sequence and applying an
-		 * exponential filter with parameter 1/16 to generate the
-		 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
-		 * D(i-1,i) is difference in latency of two consecutive packets
-		 * i-1 and i.
-		 * Reference: Calculated as per RFC 5481, sec 4.1,
-		 * RFC 3393 sec 4.5, RFC 1889 sec.
-		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency)
-					- glob_stats->jitter)/16;
-		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency;
-		else if (latency < glob_stats->min_latency)
+		if (unlikely(first_sample)) {
+			first_sample = false;
+
 			glob_stats->min_latency = latency;
-		else if (latency > glob_stats->max_latency)
 			glob_stats->max_latency = latency;
-		/*
-		 * The average latency is measured using exponential moving
-		 * average, i.e. using EWMA
-		 * https://en.wikipedia.org/wiki/Moving_average
-		 */
-		glob_stats->avg_latency +=
-			alpha * (latency - glob_stats->avg_latency);
+			glob_stats->avg_latency = latency * 4;
+			/* start ad if previous sample had 0 latency */
+			glob_stats->jitter = latency / LATENCY_JITTER_SCALE;
+		} else {
+			/*
+			 * The jitter is calculated as statistical mean of interpacket
+			 * delay variation. The "jitter estimate" is computed by taking
+			 * the absolute values of the ipdv sequence and applying an
+			 * exponential filter with parameter 1/16 to generate the
+			 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
+			 * D(i-1,i) is difference in latency of two consecutive packets
+			 * i-1 and i. Jitter is scaled by 16.
+			 * Reference: Calculated as per RFC 5481, sec 4.1,
+			 * RFC 3393 sec 4.5, RFC 1889 sec.
+			 */
+			long long delta = prev_latency - latency;
+			glob_stats->jitter += llabs(delta)
+				- glob_stats->jitter / LATENCY_JITTER_SCALE;
+
+			if (latency < glob_stats->min_latency)
+				glob_stats->min_latency = latency;
+			if (latency > glob_stats->max_latency)
+				glob_stats->max_latency = latency;
+			/*
+			 * The average latency is measured using exponential moving
+			 * average, i.e. using EWMA
+			 * https://en.wikipedia.org/wiki/Moving_average
+			 *
+			 * Alpha is .25, avg_latency is scaled by 4.
+			 */
+			glob_stats->avg_latency += latency
+				- glob_stats->avg_latency / LATENCY_AVG_SCALE;
+		}
+
 		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
-- 
2.43.0

[PATCH v5 4/9] latencystats: fix log messages

[Stephen Hemminger]

All messages that because of an error should be at log level
NOTICE or above. Do not break log messages across lines.
Reword message for the case where getting info about a port
fails and it is skipped.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 35 ++++++++++++++---------------
 1 file changed, 17 insertions(+), 18 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 2140ab87c4..c0ac60134f 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -259,7 +259,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	latency_stats_index = rte_metrics_reg_names(ptr_strings,
 							NUM_LATENCY_STATS);
 	if (latency_stats_index < 0) {
-		LATENCY_STATS_LOG(DEBUG,
+		LATENCY_STATS_LOG(ERR,
 			"Failed to register latency stats names");
 		return -1;
 	}
@@ -279,8 +279,8 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
-				"Error during getting device (port %u) info: %s",
+			LATENCY_STATS_LOG(NOTICE,
+				"Can not get info for device (port %u): %s",
 				pid, strerror(-ret));
 
 			continue;
@@ -291,18 +291,18 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
 					add_time_stamps, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
 					calc_latency, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 	return 0;
@@ -323,10 +323,9 @@ rte_latencystats_uninit(void)
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
-				"Error during getting device (port %u) info: %s",
+			LATENCY_STATS_LOG(NOTICE,
+				"Can not get info for device (port %u): %s",
 				pid, strerror(-ret));
-
 			continue;
 		}
 
@@ -334,17 +333,17 @@ rte_latencystats_uninit(void)
 			cbs = &rx_cbs[pid][qid];
 			ret = rte_eth_remove_rx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			ret = rte_eth_remove_tx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 
-- 
2.43.0

[PATCH v5 5/9] latencystats: update include files

[Stephen Hemminger]

Include what is used here.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 19 ++++++++++++++-----
 1 file changed, 14 insertions(+), 5 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index c0ac60134f..bd8fde2f0c 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,17 +2,26 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
+#include <errno.h>
 #include <math.h>
+#include <stdbool.h>
+#include <stddef.h>
+#include <stdlib.h>
+#include <string.h>
 
 #include <rte_common.h>
-#include <rte_string_fns.h>
-#include <rte_mbuf_dyn.h>
-#include <rte_log.h>
 #include <rte_cycles.h>
+#include <rte_eal.h>
+#include <rte_errno.h>
 #include <rte_ethdev.h>
-#include <rte_metrics.h>
-#include <rte_memzone.h>
 #include <rte_lcore.h>
+#include <rte_log.h>
+#include <rte_mbuf.h>
+#include <rte_mbuf_dyn.h>
+#include <rte_memzone.h>
+#include <rte_metrics.h>
+#include <rte_spinlock.h>
+#include <rte_string_fns.h>
 
 #include "rte_latencystats.h"
 
-- 
2.43.0

[PATCH v5 6/9] latencystats: enforce that unused callback function is NULL

[Stephen Hemminger]

ISO C does not allow casting function pointer to void *.
Resolve by enforcing the reserved argument.
The user_cb argument for rte_latencystats_init() was not
implemented, and had to be NULL anyway.

The log type is local to this function and therefore
can be local to this file.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index bd8fde2f0c..8311adb411 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -30,7 +30,7 @@
 
 static double cycles_per_ns;
 
-RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
+static RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
 #define LATENCY_STATS_LOG(level, ...) \
 	RTE_LOG_LINE(level, LATENCY_STATS, "" __VA_ARGS__)
@@ -246,6 +246,10 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	if (rte_memzone_lookup(MZ_RTE_LATENCY_STATS))
 		return -EEXIST;
 
+	/** Reserved for possible future use */
+	if (user_cb != NULL)
+		return -ENOTSUP;
+
 	/** Allocate stats in shared memory fo multi process support */
 	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*glob_stats),
 					rte_socket_id(), flags);
@@ -298,7 +302,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
 			cbs = &rx_cbs[pid][qid];
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
-					add_time_stamps, user_cb);
+					add_time_stamps, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Rx callback for pid=%u, qid=%u",
@@ -307,7 +311,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
-					calc_latency, user_cb);
+					calc_latency, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Tx callback for pid=%u, qid=%u",
-- 
2.43.0

[PATCH v5 7/9] latencystats: add metric for number of samples

[Stephen Hemminger]

Keeping track of the number of samples is useful when doing
debug and testing to make sure that samples are actually happening.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 20 ++++++++++++--------
 1 file changed, 12 insertions(+), 8 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 8311adb411..e5a84fbd92 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -59,6 +59,7 @@ struct rte_latency_stats {
 	uint64_t avg_latency; /**< Average latency */
 	uint64_t max_latency; /**< Maximum latency */
 	uint64_t jitter; /** Latency variation */
+	uint64_t samples;    /** Number of latency samples */
 	rte_spinlock_t lock; /** Latency calculation lock */
 };
 
@@ -82,20 +83,26 @@ static const struct latency_stats_nameoff lat_stats_strings[] = {
 	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency), LATENCY_AVG_SCALE},
 	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency), 1},
 	{"jitter_ns", offsetof(struct rte_latency_stats, jitter), LATENCY_JITTER_SCALE},
+	{"samples", offsetof(struct rte_latency_stats, samples), 0},
 };
 
-#define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
-				sizeof(lat_stats_strings[0]))
+#define NUM_LATENCY_STATS RTE_DIM(lat_stats_strings)
 
 static void
 latencystats_collect(uint64_t values[])
 {
-	unsigned int i;
+	unsigned int i, scale;
 	const uint64_t *stats;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
 		stats = RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
-		values[i] = floor(*stats / (cycles_per_ns * lat_stats_strings[i].scale));
+		scale = lat_stats_strings[i].scale;
+
+		/* used to mark samples which are not a time interval */
+		if (scale == 0)
+			values[i] = *stats;
+		else
+			values[i] = floor(*stats / (cycles_per_ns * scale));
 	}
 }
 
@@ -173,7 +180,6 @@ calc_latency(uint16_t pid __rte_unused,
 	unsigned int i;
 	uint64_t now, latency;
 	static uint64_t prev_latency;
-	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -184,9 +190,7 @@ calc_latency(uint16_t pid __rte_unused,
 
 		latency = now - *timestamp_dynfield(pkts[i]);
 
-		if (unlikely(first_sample)) {
-			first_sample = false;
-
+		if (glob_stats->samples++ == 0) {
 			glob_stats->min_latency = latency;
 			glob_stats->max_latency = latency;
 			glob_stats->avg_latency = latency * 4;
-- 
2.43.0

[PATCH v5 8/9] test: use initialization in latencystats test

[Stephen Hemminger]

No need for loop and memset() here. Just use structure
initialization.  Remove unnecessary initializations.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 app/test/test_latencystats.c | 22 +++++++---------------
 1 file changed, 7 insertions(+), 15 deletions(-)

diff --git a/app/test/test_latencystats.c b/app/test/test_latencystats.c
index c309ab194f..3369c8bb90 100644
--- a/app/test/test_latencystats.c
+++ b/app/test/test_latencystats.c
@@ -21,7 +21,7 @@
 static uint16_t portid;
 static struct rte_ring *ring;
 
-static struct rte_metric_name lat_stats_strings[] = {
+static struct rte_metric_name lat_stats_strings[NUM_STATS] = {
 	{"min_latency_ns"},
 	{"avg_latency_ns"},
 	{"max_latency_ns"},
@@ -70,13 +70,9 @@ static int test_latency_uninit(void)
 /* Test case to get names of latency stats */
 static int test_latencystats_get_names(void)
 {
-	int ret = 0, i = 0;
-	int size = 0;
-	struct rte_metric_name names[NUM_STATS];
-
-	size_t m_size = sizeof(struct rte_metric_name);
-	for (i = 0; i < NUM_STATS; i++)
-		memset(&names[i], 0, m_size);
+	int ret, i;
+	uint16_t size;
+	struct rte_metric_name names[NUM_STATS] = { };
 
 	/* Success Test: Valid names and size */
 	size = NUM_STATS;
@@ -106,13 +102,9 @@ static int test_latencystats_get_names(void)
 /* Test case to get latency stats values */
 static int test_latencystats_get(void)
 {
-	int ret = 0, i = 0;
-	int size = 0;
-	struct rte_metric_value values[NUM_STATS];
-
-	size_t v_size = sizeof(struct rte_metric_value);
-	for (i = 0; i < NUM_STATS; i++)
-		memset(&values[i], 0, v_size);
+	int ret;
+	uint16_t size;
+	struct rte_metric_value values[NUM_STATS] = { };
 
 	/* Success Test: Valid values and valid size */
 	size = NUM_STATS;
-- 
2.43.0

[PATCH v5 9/9] test: add more latencystats tests

[Stephen Hemminger]

Look at the number of samples, min, max and average
numbers to make sure they look correct.
Forward for to make sure multiple samples are taken.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 app/test/test_latencystats.c | 62 +++++++++++++++++++++++++++++-------
 1 file changed, 50 insertions(+), 12 deletions(-)

diff --git a/app/test/test_latencystats.c b/app/test/test_latencystats.c
index 3369c8bb90..676a99d385 100644
--- a/app/test/test_latencystats.c
+++ b/app/test/test_latencystats.c
@@ -14,7 +14,7 @@
 #include "sample_packet_forward.h"
 #include "test.h"
 
-#define NUM_STATS 4
+#define NUM_STATS 5
 #define LATENCY_NUM_PACKETS 10
 #define QUEUE_ID 0
 
@@ -26,6 +26,7 @@ static struct rte_metric_name lat_stats_strings[NUM_STATS] = {
 	{"avg_latency_ns"},
 	{"max_latency_ns"},
 	{"jitter_ns"},
+	{"samples"},
 };
 
 /* Test case for latency init with metrics init */
@@ -141,10 +142,14 @@ static void test_latency_ring_free(void)
 
 static int test_latency_packet_forward(void)
 {
+	unsigned int i;
 	int ret;
 	struct rte_mbuf *pbuf[LATENCY_NUM_PACKETS] = { };
 	struct rte_mempool *mp;
 	char poolname[] = "mbuf_pool";
+	uint64_t end_cycles;
+	struct rte_metric_value values[NUM_STATS] = { };
+	struct rte_metric_name names[NUM_STATS] = { };
 
 	ret = test_get_mbuf_from_pool(&mp, pbuf, poolname);
 	if (ret < 0) {
@@ -158,9 +163,41 @@ static int test_latency_packet_forward(void)
 		return TEST_FAILED;
 	}
 
-	ret = test_packet_forward(pbuf, portid, QUEUE_ID);
-	if (ret < 0)
-		printf("send pkts Failed\n");
+	ret = rte_latencystats_get_names(names, NUM_STATS);
+	TEST_ASSERT((ret == NUM_STATS), "Test Failed to get metrics names");
+
+	ret = rte_latencystats_get(values, NUM_STATS);
+	TEST_ASSERT(ret == NUM_STATS, "Test failed to get results before forwarding");
+	TEST_ASSERT(values[4].value == 0, "Samples not zero at start of test");
+
+	/*
+	 * Want test to run long enough to collect sufficient samples
+	 * but not so long that scheduler decides to reschedule it (1000 hz).
+	 */
+	end_cycles = rte_rdtsc() + rte_get_tsc_hz() / 2000;
+	do {
+		ret = test_packet_forward(pbuf, portid, QUEUE_ID);
+		if (ret < 0)
+			printf("send pkts Failed\n");
+	} while (rte_rdtsc() < end_cycles);
+
+	ret = rte_latencystats_get(values, NUM_STATS);
+	TEST_ASSERT(ret == NUM_STATS, "Test failed to get results after forwarding");
+
+	for (i = 0; i < NUM_STATS; i++) {
+		uint16_t k = values[i].key;
+
+		printf("%s = %"PRIu64"\n",
+		       names[k].name, values[i].value);
+	}
+
+	TEST_ASSERT(values[4].value > 0, "No samples taken");
+	TEST_ASSERT(values[0].value > 0, "Min latency should not be zero");
+	TEST_ASSERT(values[1].value > 0, "Avg latency should not be zero");
+	TEST_ASSERT(values[2].value > 0, "Max latency should not be zero");
+	TEST_ASSERT(values[0].value < values[1].value, "Min latency > Avg latency");
+	TEST_ASSERT(values[0].value < values[2].value, "Min latency > Max latency");
+	TEST_ASSERT(values[1].value < values[2].value, "Avg latency > Max latency");
 
 	rte_eth_dev_stop(portid);
 	test_put_mbuf_to_pool(mp, pbuf);
@@ -180,22 +217,23 @@ unit_test_suite latencystats_testsuite = {
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latency_init),
 
-		/* Test Case 2: Do packet forwarding for metrics
-		 * calculation and check the latency metrics values
-		 * are updated
-		 */
-		TEST_CASE_ST(test_latency_packet_forward, NULL,
-				test_latency_update),
-		/* Test Case 3: To check whether latency stats names
+		/* Test Case 2: To check whether latency stats names
 		 * are retrieved
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latencystats_get_names),
 
-		/* Test Case 4: To check whether latency stats
+		/* Test Case 3: To check whether latency stats
 		 * values are retrieved
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latencystats_get),
 
+		/* Test Case 4: Do packet forwarding for metrics
+		 * calculation and check the latency metrics values
+		 * are updated
+		 */
+		TEST_CASE_ST(test_latency_packet_forward, NULL,
+				test_latency_update),
+
 		/* Test Case 5: To check uninit of latency test */
 		TEST_CASE_ST(NULL, NULL, test_latency_uninit),
 
-- 
2.43.0

[PATCH v6 0/8] latencystats: improvements to algorithm and test

[Stephen Hemminger]

Latencystats uses unnecessary floating point and is inaccurate if the number
of cycles per ns is not an integral value. Cleanup the code and add
more tests as well.

v6 - rebase and combine updates to test

Stephen Hemminger (8):
  latencystats: replace use of VLA
  latencystats: handle fractional cycles per ns
  latencystats: do not use floating point
  latencystats: fix log messages
  latencystats: update include files
  latencystats: enforce that unused callback function is NULL
  latencystats: add metric for number of samples
  test: update to latencystats tests

 app/test/test_latencystats.c        |  84 ++++++----
 lib/latencystats/rte_latencystats.c | 232 ++++++++++++++++------------
 2 files changed, 188 insertions(+), 128 deletions(-)

-- 
2.43.0

[PATCH v6 1/8] latencystats: replace use of VLA

[Stephen Hemminger]

The temporary array latencystats is not needed if the algorithm
is converted into one pass.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 31 +++++++++++++++--------------
 1 file changed, 16 insertions(+), 15 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index cae4b50878..3fb8321484 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -157,9 +157,9 @@ calc_latency(uint16_t pid __rte_unused,
 		uint16_t nb_pkts,
 		void *_ __rte_unused)
 {
-	unsigned int i, cnt = 0;
+	unsigned int i;
 	uint64_t now;
-	float latency[nb_pkts];
+	float latency;
 	static float prev_latency;
 	/*
 	 * Alpha represents degree of weighting decrease in EWMA,
@@ -169,13 +169,14 @@ calc_latency(uint16_t pid __rte_unused,
 	const float alpha = 0.2f;
 
 	now = rte_rdtsc();
-	for (i = 0; i < nb_pkts; i++) {
-		if (pkts[i]->ol_flags & timestamp_dynflag)
-			latency[cnt++] = now - *timestamp_dynfield(pkts[i]);
-	}
 
 	rte_spinlock_lock(&glob_stats->lock);
-	for (i = 0; i < cnt; i++) {
+	for (i = 0; i < nb_pkts; i++) {
+		if (!(pkts[i]->ol_flags & timestamp_dynflag))
+			continue;
+
+		latency = now - *timestamp_dynfield(pkts[i]);
+
 		/*
 		 * The jitter is calculated as statistical mean of interpacket
 		 * delay variation. The "jitter estimate" is computed by taking
@@ -187,22 +188,22 @@ calc_latency(uint16_t pid __rte_unused,
 		 * Reference: Calculated as per RFC 5481, sec 4.1,
 		 * RFC 3393 sec 4.5, RFC 1889 sec.
 		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency[i])
+		glob_stats->jitter +=  (fabsf(prev_latency - latency)
 					- glob_stats->jitter)/16;
 		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] < glob_stats->min_latency)
-			glob_stats->min_latency = latency[i];
-		else if (latency[i] > glob_stats->max_latency)
-			glob_stats->max_latency = latency[i];
+			glob_stats->min_latency = latency;
+		else if (latency < glob_stats->min_latency)
+			glob_stats->min_latency = latency;
+		else if (latency > glob_stats->max_latency)
+			glob_stats->max_latency = latency;
 		/*
 		 * The average latency is measured using exponential moving
 		 * average, i.e. using EWMA
 		 * https://en.wikipedia.org/wiki/Moving_average
 		 */
 		glob_stats->avg_latency +=
-			alpha * (latency[i] - glob_stats->avg_latency);
-		prev_latency = latency[i];
+			alpha * (latency - glob_stats->avg_latency);
+		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
 
-- 
2.43.0

[PATCH v6 2/8] latencystats: handle fractional cycles per ns

[Stephen Hemminger]

The TSC frequency is not always an integral number of nanoseconds.
For examples, cycles per nanoseconds on my test system is 2.8.
Fix by using floating point where needed and calculate value once.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 3fb8321484..c897df03c6 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -18,12 +18,7 @@
 /** Nano seconds per second */
 #define NS_PER_SEC 1E9
 
-/** Clock cycles per nano second */
-static uint64_t
-latencystat_cycles_per_ns(void)
-{
-	return rte_get_timer_hz() / NS_PER_SEC;
-}
+static double cycles_per_ns;
 
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
@@ -89,8 +84,7 @@ rte_latencystats_update(void)
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
-		values[i] = (uint64_t)floor((*stats_ptr)/
-				latencystat_cycles_per_ns());
+		values[i] = floor(*stats_ptr / cycles_per_ns);
 	}
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
@@ -112,8 +106,7 @@ rte_latencystats_fill_values(struct rte_metric_value *values)
 		stats_ptr = RTE_PTR_ADD(glob_stats,
 				lat_stats_strings[i].offset);
 		values[i].key = i;
-		values[i].value = (uint64_t)floor((*stats_ptr)/
-						latencystat_cycles_per_ns());
+		values[i].value = floor(*stats_ptr / cycles_per_ns);
 	}
 }
 
@@ -235,9 +228,11 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		return -ENOMEM;
 	}
 
+	cycles_per_ns = (double)rte_get_tsc_hz() / NS_PER_SEC;
+
 	glob_stats = mz->addr;
 	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	samp_intvl = (uint64_t)(app_samp_intvl * cycles_per_ns);
 
 	/** Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
-- 
2.43.0

[PATCH v6 3/8] latencystats: do not use floating point

[Stephen Hemminger]

The cycle counts do not need to be stored as floating point.
Instead keep track of latency in cycles, and convert to
nanoseconds when read.

Use scaled math with exponential Weighted Moving Average weight
of .25 to avoid use of floating point for that.

The average latency took too long to "warm up".
Do what RFC 6298 suggests and initialize on first sample.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
Acked-by: Morten Brørup <mb@smartsharesystems.com>
---
 lib/latencystats/rte_latencystats.c | 128 ++++++++++++++++------------
 1 file changed, 73 insertions(+), 55 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index c897df03c6..2140ab87c4 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -4,6 +4,7 @@
 
 #include <math.h>
 
+#include <rte_common.h>
 #include <rte_string_fns.h>
 #include <rte_mbuf_dyn.h>
 #include <rte_log.h>
@@ -41,11 +42,14 @@ static uint64_t samp_intvl;
 static uint64_t timer_tsc;
 static uint64_t prev_tsc;
 
+#define LATENCY_AVG_SCALE     4
+#define LATENCY_JITTER_SCALE 16
+
 struct rte_latency_stats {
-	float min_latency; /**< Minimum latency in nano seconds */
-	float avg_latency; /**< Average latency in nano seconds */
-	float max_latency; /**< Maximum latency in nano seconds */
-	float jitter; /** Latency variation */
+	uint64_t min_latency; /**< Minimum latency */
+	uint64_t avg_latency; /**< Average latency */
+	uint64_t max_latency; /**< Maximum latency */
+	uint64_t jitter; /** Latency variation */
 	rte_spinlock_t lock; /** Latency calculation lock */
 };
 
@@ -61,31 +65,38 @@ static struct rxtx_cbs tx_cbs[RTE_MAX_ETHPORTS][RTE_MAX_QUEUES_PER_PORT];
 struct latency_stats_nameoff {
 	char name[RTE_ETH_XSTATS_NAME_SIZE];
 	unsigned int offset;
+	unsigned int scale;
 };
 
 static const struct latency_stats_nameoff lat_stats_strings[] = {
-	{"min_latency_ns", offsetof(struct rte_latency_stats, min_latency)},
-	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency)},
-	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency)},
-	{"jitter_ns", offsetof(struct rte_latency_stats, jitter)},
+	{"min_latency_ns", offsetof(struct rte_latency_stats, min_latency), 1},
+	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency), LATENCY_AVG_SCALE},
+	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency), 1},
+	{"jitter_ns", offsetof(struct rte_latency_stats, jitter), LATENCY_JITTER_SCALE},
 };
 
 #define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
 				sizeof(lat_stats_strings[0]))
 
-int32_t
-rte_latencystats_update(void)
+static void
+latencystats_collect(uint64_t values[])
 {
 	unsigned int i;
-	float *stats_ptr = NULL;
-	uint64_t values[NUM_LATENCY_STATS] = {0};
-	int ret;
+	const uint64_t *stats;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i] = floor(*stats_ptr / cycles_per_ns);
+		stats = RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
+		values[i] = floor(*stats / (cycles_per_ns * lat_stats_strings[i].scale));
 	}
+}
+
+int32_t
+rte_latencystats_update(void)
+{
+	uint64_t values[NUM_LATENCY_STATS];
+	int ret;
+
+	latencystats_collect(values);
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
 					latency_stats_index,
@@ -97,16 +108,16 @@ rte_latencystats_update(void)
 }
 
 static void
-rte_latencystats_fill_values(struct rte_metric_value *values)
+rte_latencystats_fill_values(struct rte_metric_value *metrics)
 {
+	uint64_t values[NUM_LATENCY_STATS];
 	unsigned int i;
-	float *stats_ptr = NULL;
+
+	latencystats_collect(values);
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
-		stats_ptr = RTE_PTR_ADD(glob_stats,
-				lat_stats_strings[i].offset);
-		values[i].key = i;
-		values[i].value = floor(*stats_ptr / cycles_per_ns);
+		metrics[i].key = i;
+		metrics[i].value = values[i];
 	}
 }
 
@@ -151,15 +162,9 @@ calc_latency(uint16_t pid __rte_unused,
 		void *_ __rte_unused)
 {
 	unsigned int i;
-	uint64_t now;
-	float latency;
-	static float prev_latency;
-	/*
-	 * Alpha represents degree of weighting decrease in EWMA,
-	 * a constant smoothing factor between 0 and 1. The value
-	 * is used below for measuring average latency.
-	 */
-	const float alpha = 0.2f;
+	uint64_t now, latency;
+	static uint64_t prev_latency;
+	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -170,32 +175,45 @@ calc_latency(uint16_t pid __rte_unused,
 
 		latency = now - *timestamp_dynfield(pkts[i]);
 
-		/*
-		 * The jitter is calculated as statistical mean of interpacket
-		 * delay variation. The "jitter estimate" is computed by taking
-		 * the absolute values of the ipdv sequence and applying an
-		 * exponential filter with parameter 1/16 to generate the
-		 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
-		 * D(i-1,i) is difference in latency of two consecutive packets
-		 * i-1 and i.
-		 * Reference: Calculated as per RFC 5481, sec 4.1,
-		 * RFC 3393 sec 4.5, RFC 1889 sec.
-		 */
-		glob_stats->jitter +=  (fabsf(prev_latency - latency)
-					- glob_stats->jitter)/16;
-		if (glob_stats->min_latency == 0)
-			glob_stats->min_latency = latency;
-		else if (latency < glob_stats->min_latency)
+		if (unlikely(first_sample)) {
+			first_sample = false;
+
 			glob_stats->min_latency = latency;
-		else if (latency > glob_stats->max_latency)
 			glob_stats->max_latency = latency;
-		/*
-		 * The average latency is measured using exponential moving
-		 * average, i.e. using EWMA
-		 * https://en.wikipedia.org/wiki/Moving_average
-		 */
-		glob_stats->avg_latency +=
-			alpha * (latency - glob_stats->avg_latency);
+			glob_stats->avg_latency = latency * 4;
+			/* start ad if previous sample had 0 latency */
+			glob_stats->jitter = latency / LATENCY_JITTER_SCALE;
+		} else {
+			/*
+			 * The jitter is calculated as statistical mean of interpacket
+			 * delay variation. The "jitter estimate" is computed by taking
+			 * the absolute values of the ipdv sequence and applying an
+			 * exponential filter with parameter 1/16 to generate the
+			 * estimate. i.e J=J+(|D(i-1,i)|-J)/16. Where J is jitter,
+			 * D(i-1,i) is difference in latency of two consecutive packets
+			 * i-1 and i. Jitter is scaled by 16.
+			 * Reference: Calculated as per RFC 5481, sec 4.1,
+			 * RFC 3393 sec 4.5, RFC 1889 sec.
+			 */
+			long long delta = prev_latency - latency;
+			glob_stats->jitter += llabs(delta)
+				- glob_stats->jitter / LATENCY_JITTER_SCALE;
+
+			if (latency < glob_stats->min_latency)
+				glob_stats->min_latency = latency;
+			if (latency > glob_stats->max_latency)
+				glob_stats->max_latency = latency;
+			/*
+			 * The average latency is measured using exponential moving
+			 * average, i.e. using EWMA
+			 * https://en.wikipedia.org/wiki/Moving_average
+			 *
+			 * Alpha is .25, avg_latency is scaled by 4.
+			 */
+			glob_stats->avg_latency += latency
+				- glob_stats->avg_latency / LATENCY_AVG_SCALE;
+		}
+
 		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
-- 
2.43.0

[PATCH v6 4/8] latencystats: fix log messages

[Stephen Hemminger]

All messages that because of an error should be at log level
NOTICE or above. Do not break log messages across lines.
Reword message for the case where getting info about a port
fails and it is skipped.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>
---
 lib/latencystats/rte_latencystats.c | 35 ++++++++++++++---------------
 1 file changed, 17 insertions(+), 18 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 2140ab87c4..c0ac60134f 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -259,7 +259,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	latency_stats_index = rte_metrics_reg_names(ptr_strings,
 							NUM_LATENCY_STATS);
 	if (latency_stats_index < 0) {
-		LATENCY_STATS_LOG(DEBUG,
+		LATENCY_STATS_LOG(ERR,
 			"Failed to register latency stats names");
 		return -1;
 	}
@@ -279,8 +279,8 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
-				"Error during getting device (port %u) info: %s",
+			LATENCY_STATS_LOG(NOTICE,
+				"Can not get info for device (port %u): %s",
 				pid, strerror(-ret));
 
 			continue;
@@ -291,18 +291,18 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
 					add_time_stamps, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
 					calc_latency, user_cb);
 			if (!cbs->cb)
-				LATENCY_STATS_LOG(INFO, "Failed to "
-					"register Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to register Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 	return 0;
@@ -323,10 +323,9 @@ rte_latencystats_uninit(void)
 
 		ret = rte_eth_dev_info_get(pid, &dev_info);
 		if (ret != 0) {
-			LATENCY_STATS_LOG(INFO,
-				"Error during getting device (port %u) info: %s",
+			LATENCY_STATS_LOG(NOTICE,
+				"Can not get info for device (port %u): %s",
 				pid, strerror(-ret));
-
 			continue;
 		}
 
@@ -334,17 +333,17 @@ rte_latencystats_uninit(void)
 			cbs = &rx_cbs[pid][qid];
 			ret = rte_eth_remove_rx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Rx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Rx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			ret = rte_eth_remove_tx_callback(pid, qid, cbs->cb);
 			if (ret)
-				LATENCY_STATS_LOG(INFO, "failed to "
-					"remove Tx callback for pid=%d, "
-					"qid=%d", pid, qid);
+				LATENCY_STATS_LOG(NOTICE,
+					"Failed to remove Tx callback for pid=%u, qid=%u",
+					pid, qid);
 		}
 	}
 
-- 
2.43.0

[PATCH v6 5/8] latencystats: update include files

[Stephen Hemminger]

Include what is used here.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 19 ++++++++++++++-----
 1 file changed, 14 insertions(+), 5 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index c0ac60134f..bd8fde2f0c 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,17 +2,26 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
+#include <errno.h>
 #include <math.h>
+#include <stdbool.h>
+#include <stddef.h>
+#include <stdlib.h>
+#include <string.h>
 
 #include <rte_common.h>
-#include <rte_string_fns.h>
-#include <rte_mbuf_dyn.h>
-#include <rte_log.h>
 #include <rte_cycles.h>
+#include <rte_eal.h>
+#include <rte_errno.h>
 #include <rte_ethdev.h>
-#include <rte_metrics.h>
-#include <rte_memzone.h>
 #include <rte_lcore.h>
+#include <rte_log.h>
+#include <rte_mbuf.h>
+#include <rte_mbuf_dyn.h>
+#include <rte_memzone.h>
+#include <rte_metrics.h>
+#include <rte_spinlock.h>
+#include <rte_string_fns.h>
 
 #include "rte_latencystats.h"
 
-- 
2.43.0

[PATCH v6 6/8] latencystats: enforce that unused callback function is NULL

[Stephen Hemminger]

ISO C does not allow casting function pointer to void *.
Resolve by enforcing the reserved argument.
The user_cb argument for rte_latencystats_init() was not
implemented, and had to be NULL anyway.

The log type is local to this function and therefore
can be local to this file.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index bd8fde2f0c..8311adb411 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -30,7 +30,7 @@
 
 static double cycles_per_ns;
 
-RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
+static RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
 #define RTE_LOGTYPE_LATENCY_STATS latencystat_logtype
 #define LATENCY_STATS_LOG(level, ...) \
 	RTE_LOG_LINE(level, LATENCY_STATS, "" __VA_ARGS__)
@@ -246,6 +246,10 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 	if (rte_memzone_lookup(MZ_RTE_LATENCY_STATS))
 		return -EEXIST;
 
+	/** Reserved for possible future use */
+	if (user_cb != NULL)
+		return -ENOTSUP;
+
 	/** Allocate stats in shared memory fo multi process support */
 	mz = rte_memzone_reserve(MZ_RTE_LATENCY_STATS, sizeof(*glob_stats),
 					rte_socket_id(), flags);
@@ -298,7 +302,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_rx_queues; qid++) {
 			cbs = &rx_cbs[pid][qid];
 			cbs->cb = rte_eth_add_first_rx_callback(pid, qid,
-					add_time_stamps, user_cb);
+					add_time_stamps, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Rx callback for pid=%u, qid=%u",
@@ -307,7 +311,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 		for (qid = 0; qid < dev_info.nb_tx_queues; qid++) {
 			cbs = &tx_cbs[pid][qid];
 			cbs->cb =  rte_eth_add_tx_callback(pid, qid,
-					calc_latency, user_cb);
+					calc_latency, NULL);
 			if (!cbs->cb)
 				LATENCY_STATS_LOG(NOTICE,
 					"Failed to register Tx callback for pid=%u, qid=%u",
-- 
2.43.0

[PATCH v6 7/8] latencystats: add metric for number of samples

[Stephen Hemminger]

Keeping track of the number of samples is useful when doing
debug and testing to make sure that samples are actually happening.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 lib/latencystats/rte_latencystats.c | 20 ++++++++++++--------
 1 file changed, 12 insertions(+), 8 deletions(-)

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 8311adb411..e5a84fbd92 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -59,6 +59,7 @@ struct rte_latency_stats {
 	uint64_t avg_latency; /**< Average latency */
 	uint64_t max_latency; /**< Maximum latency */
 	uint64_t jitter; /** Latency variation */
+	uint64_t samples;    /** Number of latency samples */
 	rte_spinlock_t lock; /** Latency calculation lock */
 };
 
@@ -82,20 +83,26 @@ static const struct latency_stats_nameoff lat_stats_strings[] = {
 	{"avg_latency_ns", offsetof(struct rte_latency_stats, avg_latency), LATENCY_AVG_SCALE},
 	{"max_latency_ns", offsetof(struct rte_latency_stats, max_latency), 1},
 	{"jitter_ns", offsetof(struct rte_latency_stats, jitter), LATENCY_JITTER_SCALE},
+	{"samples", offsetof(struct rte_latency_stats, samples), 0},
 };
 
-#define NUM_LATENCY_STATS (sizeof(lat_stats_strings) / \
-				sizeof(lat_stats_strings[0]))
+#define NUM_LATENCY_STATS RTE_DIM(lat_stats_strings)
 
 static void
 latencystats_collect(uint64_t values[])
 {
-	unsigned int i;
+	unsigned int i, scale;
 	const uint64_t *stats;
 
 	for (i = 0; i < NUM_LATENCY_STATS; i++) {
 		stats = RTE_PTR_ADD(glob_stats, lat_stats_strings[i].offset);
-		values[i] = floor(*stats / (cycles_per_ns * lat_stats_strings[i].scale));
+		scale = lat_stats_strings[i].scale;
+
+		/* used to mark samples which are not a time interval */
+		if (scale == 0)
+			values[i] = *stats;
+		else
+			values[i] = floor(*stats / (cycles_per_ns * scale));
 	}
 }
 
@@ -173,7 +180,6 @@ calc_latency(uint16_t pid __rte_unused,
 	unsigned int i;
 	uint64_t now, latency;
 	static uint64_t prev_latency;
-	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -184,9 +190,7 @@ calc_latency(uint16_t pid __rte_unused,
 
 		latency = now - *timestamp_dynfield(pkts[i]);
 
-		if (unlikely(first_sample)) {
-			first_sample = false;
-
+		if (glob_stats->samples++ == 0) {
 			glob_stats->min_latency = latency;
 			glob_stats->max_latency = latency;
 			glob_stats->avg_latency = latency * 4;
-- 
2.43.0

[PATCH v6 8/8] test: update to latencystats tests

[Stephen Hemminger]

No need for loop and memset() here. Just use structure
initialization.  Remove unnecessary initializations.

Look at the number of samples, min, max and average
numbers to make sure they look correct.
Forward for longer to make sure multiple samples are taken.

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 app/test/test_latencystats.c | 84 ++++++++++++++++++++++++------------
 1 file changed, 57 insertions(+), 27 deletions(-)

diff --git a/app/test/test_latencystats.c b/app/test/test_latencystats.c
index c309ab194f..676a99d385 100644
--- a/app/test/test_latencystats.c
+++ b/app/test/test_latencystats.c
@@ -14,18 +14,19 @@
 #include "sample_packet_forward.h"
 #include "test.h"
 
-#define NUM_STATS 4
+#define NUM_STATS 5
 #define LATENCY_NUM_PACKETS 10
 #define QUEUE_ID 0
 
 static uint16_t portid;
 static struct rte_ring *ring;
 
-static struct rte_metric_name lat_stats_strings[] = {
+static struct rte_metric_name lat_stats_strings[NUM_STATS] = {
 	{"min_latency_ns"},
 	{"avg_latency_ns"},
 	{"max_latency_ns"},
 	{"jitter_ns"},
+	{"samples"},
 };
 
 /* Test case for latency init with metrics init */
@@ -70,13 +71,9 @@ static int test_latency_uninit(void)
 /* Test case to get names of latency stats */
 static int test_latencystats_get_names(void)
 {
-	int ret = 0, i = 0;
-	int size = 0;
-	struct rte_metric_name names[NUM_STATS];
-
-	size_t m_size = sizeof(struct rte_metric_name);
-	for (i = 0; i < NUM_STATS; i++)
-		memset(&names[i], 0, m_size);
+	int ret, i;
+	uint16_t size;
+	struct rte_metric_name names[NUM_STATS] = { };
 
 	/* Success Test: Valid names and size */
 	size = NUM_STATS;
@@ -106,13 +103,9 @@ static int test_latencystats_get_names(void)
 /* Test case to get latency stats values */
 static int test_latencystats_get(void)
 {
-	int ret = 0, i = 0;
-	int size = 0;
-	struct rte_metric_value values[NUM_STATS];
-
-	size_t v_size = sizeof(struct rte_metric_value);
-	for (i = 0; i < NUM_STATS; i++)
-		memset(&values[i], 0, v_size);
+	int ret;
+	uint16_t size;
+	struct rte_metric_value values[NUM_STATS] = { };
 
 	/* Success Test: Valid values and valid size */
 	size = NUM_STATS;
@@ -149,10 +142,14 @@ static void test_latency_ring_free(void)
 
 static int test_latency_packet_forward(void)
 {
+	unsigned int i;
 	int ret;
 	struct rte_mbuf *pbuf[LATENCY_NUM_PACKETS] = { };
 	struct rte_mempool *mp;
 	char poolname[] = "mbuf_pool";
+	uint64_t end_cycles;
+	struct rte_metric_value values[NUM_STATS] = { };
+	struct rte_metric_name names[NUM_STATS] = { };
 
 	ret = test_get_mbuf_from_pool(&mp, pbuf, poolname);
 	if (ret < 0) {
@@ -166,9 +163,41 @@ static int test_latency_packet_forward(void)
 		return TEST_FAILED;
 	}
 
-	ret = test_packet_forward(pbuf, portid, QUEUE_ID);
-	if (ret < 0)
-		printf("send pkts Failed\n");
+	ret = rte_latencystats_get_names(names, NUM_STATS);
+	TEST_ASSERT((ret == NUM_STATS), "Test Failed to get metrics names");
+
+	ret = rte_latencystats_get(values, NUM_STATS);
+	TEST_ASSERT(ret == NUM_STATS, "Test failed to get results before forwarding");
+	TEST_ASSERT(values[4].value == 0, "Samples not zero at start of test");
+
+	/*
+	 * Want test to run long enough to collect sufficient samples
+	 * but not so long that scheduler decides to reschedule it (1000 hz).
+	 */
+	end_cycles = rte_rdtsc() + rte_get_tsc_hz() / 2000;
+	do {
+		ret = test_packet_forward(pbuf, portid, QUEUE_ID);
+		if (ret < 0)
+			printf("send pkts Failed\n");
+	} while (rte_rdtsc() < end_cycles);
+
+	ret = rte_latencystats_get(values, NUM_STATS);
+	TEST_ASSERT(ret == NUM_STATS, "Test failed to get results after forwarding");
+
+	for (i = 0; i < NUM_STATS; i++) {
+		uint16_t k = values[i].key;
+
+		printf("%s = %"PRIu64"\n",
+		       names[k].name, values[i].value);
+	}
+
+	TEST_ASSERT(values[4].value > 0, "No samples taken");
+	TEST_ASSERT(values[0].value > 0, "Min latency should not be zero");
+	TEST_ASSERT(values[1].value > 0, "Avg latency should not be zero");
+	TEST_ASSERT(values[2].value > 0, "Max latency should not be zero");
+	TEST_ASSERT(values[0].value < values[1].value, "Min latency > Avg latency");
+	TEST_ASSERT(values[0].value < values[2].value, "Min latency > Max latency");
+	TEST_ASSERT(values[1].value < values[2].value, "Avg latency > Max latency");
 
 	rte_eth_dev_stop(portid);
 	test_put_mbuf_to_pool(mp, pbuf);
@@ -188,22 +217,23 @@ unit_test_suite latencystats_testsuite = {
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latency_init),
 
-		/* Test Case 2: Do packet forwarding for metrics
-		 * calculation and check the latency metrics values
-		 * are updated
-		 */
-		TEST_CASE_ST(test_latency_packet_forward, NULL,
-				test_latency_update),
-		/* Test Case 3: To check whether latency stats names
+		/* Test Case 2: To check whether latency stats names
 		 * are retrieved
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latencystats_get_names),
 
-		/* Test Case 4: To check whether latency stats
+		/* Test Case 3: To check whether latency stats
 		 * values are retrieved
 		 */
 		TEST_CASE_ST(NULL, NULL, test_latencystats_get),
 
+		/* Test Case 4: Do packet forwarding for metrics
+		 * calculation and check the latency metrics values
+		 * are updated
+		 */
+		TEST_CASE_ST(test_latency_packet_forward, NULL,
+				test_latency_update),
+
 		/* Test Case 5: To check uninit of latency test */
 		TEST_CASE_ST(NULL, NULL, test_latency_uninit),
 
-- 
2.43.0