[PATCH v3 0/5] latencystats: cleanups

[PATCH v3 0/5] latencystats: cleanups

[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.

Stephen Hemminger (5):
  latencystats: replace use of VLA
  latencystats: handle fractional cycles per ns
  latencystats: do not use floating point
  latencystats: fix log messages
  latencystats: include file cleanup

 lib/latencystats/rte_latencystats.c | 175 +++++++++++++++-------------
 1 file changed, 92 insertions(+), 83 deletions(-)

-- 
2.43.0

[PATCH v3 1/5] 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>
---
 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

RE: [PATCH v3 1/5] latencystats: replace use of VLA

[Morten Brørup]

> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Wednesday, 17 April 2024 19.07
> 
> The temporary array latencystats is not needed if the algorithm
> is converted into one pass.
> 
> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---
>  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)

You could add unlikely() to this comparison. It should only happen once in a lifetime.

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

In theory, glob_stats->max_latency should also be initialized with the first sample value here.

> +		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 min/max comparisons are also unlikely.

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

With or without suggested changes,
Acked-by: Morten Brørup <mb@smartsharesystems.com>

Re: [PATCH v3 1/5] latencystats: replace use of VLA

[Stephen Hemminger]

On Wed, 17 Apr 2024 20:03:55 +0200
Morten Brørup <mb@smartsharesystems.com> wrote:

> In theory, glob_stats->max_latency should also be initialized with the first sample value here.

The last patch does that. 
It was merge of two patches, will split up in next version.

Re: [PATCH v3 1/5] latencystats: replace use of VLA

[Tyler Retzlaff]

On Wed, Apr 17, 2024 at 10:07:23AM -0700, Stephen Hemminger wrote:
> The temporary array latencystats is not needed if the algorithm
> is converted into one pass.
> 
> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---

if this series is merged first, my series here
https://patchwork.dpdk.org/project/dpdk/patch/1713397319-26135-6-git-send-email-roretzla@linux.microsoft.com/
can just have the latencystats patch dropped, since this series carries
the preferred change.

thanks Stephen!

Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>

[PATCH v3 2/5] 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.

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

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 9b345bfb33..fe8c3c563a 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -19,10 +19,10 @@
 #define NS_PER_SEC 1E9
 
 /** Clock cycles per nano second */
-static uint64_t
+static float
 latencystat_cycles_per_ns(void)
 {
-	return rte_get_timer_hz() / NS_PER_SEC;
+	return (double)rte_get_timer_hz() / NS_PER_SEC;
 }
 
 RTE_LOG_REGISTER_DEFAULT(latencystat_logtype, INFO);
@@ -89,8 +89,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 / latencystat_cycles_per_ns());
 	}
 
 	ret = rte_metrics_update_values(RTE_METRICS_GLOBAL,
@@ -112,8 +111,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 / latencystat_cycles_per_ns());
 	}
 }
 
@@ -237,7 +235,7 @@ rte_latencystats_init(uint64_t app_samp_intvl,
 
 	glob_stats = mz->addr;
 	rte_spinlock_init(&glob_stats->lock);
-	samp_intvl = app_samp_intvl * latencystat_cycles_per_ns();
+	samp_intvl = floor(app_samp_intvl * latencystat_cycles_per_ns());
 
 	/** Register latency stats with stats library */
 	for (i = 0; i < NUM_LATENCY_STATS; i++)
-- 
2.43.0

Re: [PATCH v3 2/5] latencystats: handle fractional cycles per ns

[Tyler Retzlaff]

On Wed, Apr 17, 2024 at 10:07:24AM -0700, Stephen Hemminger wrote:
> 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.
> 
> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---
>  lib/latencystats/rte_latencystats.c | 12 +++++-------
>  1 file changed, 5 insertions(+), 7 deletions(-)
> 
> diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
> index 9b345bfb33..fe8c3c563a 100644
> --- a/lib/latencystats/rte_latencystats.c
> +++ b/lib/latencystats/rte_latencystats.c
> @@ -19,10 +19,10 @@
>  #define NS_PER_SEC 1E9
>  
>  /** Clock cycles per nano second */
> -static uint64_t
> +static float
>  latencystat_cycles_per_ns(void)
>  {
> -	return rte_get_timer_hz() / NS_PER_SEC;
> +	return (double)rte_get_timer_hz() / NS_PER_SEC;
>  }

my feeling is this will generate a warning on msvc later double ->
float.

[PATCH v3 3/5] 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.

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

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index fe8c3c563a..11bd0ea4ae 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -47,10 +47,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 */
 };
 
@@ -82,13 +82,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 / latencystat_cycles_per_ns());
 	}
 
@@ -105,11 +104,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 / latencystat_cycles_per_ns());
 	}
@@ -156,15 +154,8 @@ 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;
 
 	now = rte_rdtsc();
 
@@ -186,8 +177,7 @@ 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)
-					- glob_stats->jitter)/16;
+		glob_stats->jitter += ((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)
@@ -198,9 +188,10 @@ calc_latency(uint16_t pid __rte_unused,
 		 * 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 +=
-			alpha * (latency - glob_stats->avg_latency);
+		glob_stats->avg_latency += (latency - glob_stats->avg_latency) / 4;
 		prev_latency = latency;
 	}
 	rte_spinlock_unlock(&glob_stats->lock);
-- 
2.43.0

Re: [PATCH v3 3/5] latencystats: do not use floating point

[Tyler Retzlaff]

On Wed, Apr 17, 2024 at 10:07:25AM -0700, Stephen Hemminger wrote:
> 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.
> 
> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---
>  lib/latencystats/rte_latencystats.c | 37 +++++++++++------------------
>  1 file changed, 14 insertions(+), 23 deletions(-)
> 
> diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
> index fe8c3c563a..11bd0ea4ae 100644
> --- a/lib/latencystats/rte_latencystats.c
> +++ b/lib/latencystats/rte_latencystats.c
> @@ -47,10 +47,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 */
>  };
>  
> @@ -82,13 +82,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 / latencystat_cycles_per_ns());

will this need a cast to uint64_t?

>  	}
>  
> @@ -105,11 +104,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 / latencystat_cycles_per_ns());
>  	}
> @@ -156,15 +154,8 @@ 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;
>  

if this is merged i can abandon this series
https://patchwork.dpdk.org/project/dpdk/list/?series=31747

Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>

[PATCH v3 4/5] 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>
---
 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 11bd0ea4ae..62038a9f5d 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -235,7 +235,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;
 	}
@@ -255,7 +255,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));
 
@@ -267,18 +267,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;
@@ -299,7 +299,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));
 
@@ -310,17 +310,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

Re: [PATCH v3 4/5] latencystats: fix log messages

[Tyler Retzlaff]

On Wed, Apr 17, 2024 at 10:07:26AM -0700, Stephen Hemminger wrote:
> 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>
> ---
>  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 11bd0ea4ae..62038a9f5d 100644
> --- a/lib/latencystats/rte_latencystats.c
> +++ b/lib/latencystats/rte_latencystats.c
> @@ -235,7 +235,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;
>  	}
> @@ -255,7 +255,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",

nit: the level is notice, but the message says 'Error' same in a couple
of other instances below. arguably fine so you can ignore me.

>  				pid, strerror(-ret));
>  
> @@ -267,18 +267,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;
> @@ -299,7 +299,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));
>  
> @@ -310,17 +310,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);
>  		}
>  	}
>  
> -- 

Acked-by: Tyler Retzlaff <roretzla@linux.microsoft.com>

[PATCH v3 5/5] latencystats: include file cleanup

[Stephen Hemminger]

Include what is used here.

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

diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
index 62038a9f5d..31e7a6eb88 100644
--- a/lib/latencystats/rte_latencystats.c
+++ b/lib/latencystats/rte_latencystats.c
@@ -2,16 +2,25 @@
  * Copyright(c) 2018 Intel Corporation
  */
 
+#include <errno.h>
 #include <math.h>
+#include <stdbool.h>
+#include <stddef.h>
+#include <string.h>
 
-#include <rte_string_fns.h>
-#include <rte_mbuf_dyn.h>
-#include <rte_log.h>
+#include <rte_common.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"
 
@@ -148,14 +157,15 @@ add_time_stamps(uint16_t pid __rte_unused,
 
 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)
+	     uint16_t qid __rte_unused,
+	     struct rte_mbuf **pkts,
+	     uint16_t nb_pkts,
+	     void *_ __rte_unused)
 {
 	unsigned int i;
 	uint64_t now, latency;
 	static uint64_t prev_latency;
+	static bool first_sample = true;
 
 	now = rte_rdtsc();
 
@@ -166,32 +176,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 += ((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 (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
-		 *
-		 * Alpha is .25
-		 */
-		glob_stats->avg_latency += (latency - glob_stats->avg_latency) / 4;
+			glob_stats->avg_latency = latency;
+			glob_stats->jitter = 0;
+		} 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 v3 5/5] latencystats: include file cleanup

[Bruce Richardson]

On Wed, Apr 17, 2024 at 10:07:27AM -0700, Stephen Hemminger wrote:
> Include what is used here.
> 
There are more changes in this patch than just includes cleanup.

> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---
>  lib/latencystats/rte_latencystats.c | 85 ++++++++++++++++++-----------
>  1 file changed, 52 insertions(+), 33 deletions(-)
> 
> diff --git a/lib/latencystats/rte_latencystats.c b/lib/latencystats/rte_latencystats.c
> index 62038a9f5d..31e7a6eb88 100644
> --- a/lib/latencystats/rte_latencystats.c
> +++ b/lib/latencystats/rte_latencystats.c
> @@ -2,16 +2,25 @@
>   * Copyright(c) 2018 Intel Corporation
>   */
>  
> +#include <errno.h>
>  #include <math.h>
> +#include <stdbool.h>
> +#include <stddef.h>
> +#include <string.h>
>  
> -#include <rte_string_fns.h>
> -#include <rte_mbuf_dyn.h>
> -#include <rte_log.h>
> +#include <rte_common.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"
>  
> @@ -148,14 +157,15 @@ add_time_stamps(uint16_t pid __rte_unused,
>  
>  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)
> +	     uint16_t qid __rte_unused,
> +	     struct rte_mbuf **pkts,
> +	     uint16_t nb_pkts,
> +	     void *_ __rte_unused)
>  {
>  	unsigned int i;
>  	uint64_t now, latency;
>  	static uint64_t prev_latency;
> +	static bool first_sample = true;
>  
>  	now = rte_rdtsc();
>  
> @@ -166,32 +176,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 += ((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 (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
> -		 *
> -		 * Alpha is .25
> -		 */
> -		glob_stats->avg_latency += (latency - glob_stats->avg_latency) / 4;
> +			glob_stats->avg_latency = latency;
> +			glob_stats->jitter = 0;
> +		} 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 v3 5/5] latencystats: include file cleanup

[Stephen Hemminger]

On Wed, 17 Apr 2024 18:30:38 +0100
Bruce Richardson <bruce.richardson@intel.com> wrote:

> On Wed, Apr 17, 2024 at 10:07:27AM -0700, Stephen Hemminger wrote:
> > Include what is used here.
> >   
> There are more changes in this patch than just includes cleanup.


Sorry got two squashed on a rebase