spa: add spa_ratelimit

spa/include/spa/utils/ratelimit.h

@@ -0,0 +1,42 @@
+/* Ratelimit */
+/* SPDX-FileCopyrightText: Copyright © 2023 Wim Taymans */
+/* SPDX-License-Identifier: MIT */
+
+#ifndef SPA_RATELIMIT_H
+#define SPA_RATELIMIT_H
+
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+#include <stddef.h>
+
+struct spa_ratelimit {
+	uint64_t interval;
+	uint64_t begin;
+	unsigned burst;
+	unsigned n_printed;
+	unsigned n_missed;
+};
+
+static inline int spa_ratelimit_test(struct spa_ratelimit *r, uint64_t now)
+{
+	unsigned missed = 0;
+	if (r->begin + r->interval < now) {
+		missed = r->n_missed;
+		r->begin = now;
+		r->n_printed = 0;
+		r->n_missed = 0;
+	} else if (r->n_printed >= r->burst) {
+		r->n_missed++;
+		return -1;
+	}
+	r->n_printed++;
+	return missed;
+}
+
+#ifdef __cplusplus
+} /* extern "C" */
+#endif
+
+#endif /* SPA_RATELIMIT_H */

spa/plugins/alsa/alsa-pcm.c

@@ -1980,7 +1980,7 @@ static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes
 		if ((res = alsa_recover(state, avail)) < 0)
 			return res;
 		if ((avail = snd_pcm_avail(state->hndl)) < 0) {
-			if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+			if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 				spa_log_warn(state->log, "%s: (%d missed) snd_pcm_avail after recover: %s",
 						state->props.device, missed, snd_strerror(avail));
 			}
@@ -1997,7 +1997,7 @@ static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes
 		uint64_t then;
 
 		if ((res = snd_pcm_htimestamp(state->hndl, &havail, &tstamp)) < 0) {
-			if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+			if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 				spa_log_warn(state->log, "%s: (%d missed) snd_pcm_htimestamp error: %s",
 					state->props.device, missed, snd_strerror(res));
 			}
@@ -2025,7 +2025,7 @@ static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes
 					state->htimestamp_error = 0;
 					state->htimestamp = false;
 				}
-				else if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+				else if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 					spa_log_warn(state->log, "%s: (%d missed) impossible htimestamp diff:%"PRIi64,
 						state->props.device, missed, diff);
 				}
@@ -2253,7 +2253,7 @@ int spa_alsa_write(struct state *state)
 			else
 				lev = SPA_LOG_LEVEL_INFO;
 
-			if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+			if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 				spa_log_lev(state->log, lev, "%s: follower avail:%lu delay:%ld "
 						"target:%ld thr:%u, resync (%d missed)",
 						state->props.device, avail, delay,
@@ -2490,7 +2490,7 @@ int spa_alsa_read(struct state *state)
 			else
 				lev = SPA_LOG_LEVEL_INFO;
 
-			if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+			if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 				spa_log_lev(state->log, lev, "%s: follower delay:%ld target:%ld thr:%u, "
 						"resync (%d missed)", state->props.device, delay,
 						target, state->threshold, missed);
@@ -2743,7 +2743,7 @@ done:
 	if (!state->disable_tsched &&
 			(state->next_time > current_time + SPA_NSEC_PER_SEC ||
 			 current_time > state->next_time + SPA_NSEC_PER_SEC)) {
-		if ((missed = ratelimit_test(&state->rate_limit, current_time)) >= 0) {
+		if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
 			spa_log_error(state->log, "%s: impossible timeout %lu %lu %lu %"
 					PRIu64" %"PRIu64" %"PRIi64" %d %"PRIi64" (%d missed)",
 					state->props.device, avail, delay, target,

spa/plugins/alsa/alsa-pcm.h

@@ -21,6 +21,7 @@ extern "C" {
 #include <spa/utils/list.h>
 #include <spa/utils/json.h>
 #include <spa/utils/dll.h>
+#include <spa/utils/ratelimit.h>
 
 #include <spa/node/node.h>
 #include <spa/node/utils.h>
@@ -81,13 +82,6 @@ struct card {
 	uint32_t rate;
 };
 
-struct ratelimit {
-	uint64_t interval;
-	uint64_t begin;
-	unsigned burst;
-	unsigned n_printed, n_missed;
-};
-
 struct state {
 	struct spa_handle handle;
 	struct spa_node node;
@@ -97,7 +91,7 @@ struct state {
 	struct spa_loop *data_loop;
 
 	FILE *log_file;
-	struct ratelimit rate_limit;
+	struct spa_ratelimit rate_limit;
 
 	uint32_t card_index;
 	struct card *card;
@@ -348,22 +342,6 @@ static inline uint32_t spa_alsa_get_iec958_codecs(struct state *state, uint32_t
 	return i;
 }
 
-static inline int ratelimit_test(struct ratelimit *r, uint64_t now)
-{
-	unsigned missed = 0;
-	if (r->begin + r->interval < now) {
-		missed = r->n_missed;
-		r->begin = now;
-		r->n_printed = 0;
-		r->n_missed = 0;
-	} else if (r->n_printed >= r->burst) {
-		r->n_missed++;
-		return -1;
-	}
-	r->n_printed++;
-	return missed;
-}
-
 /* This function is also as snd_pcm_channel_area_addr() since 1.2.6 which is not yet
  * in ubuntu and I can't figure out how to do the ALSA version check. */
 static inline void *channel_area_addr(const snd_pcm_channel_area_t *area, snd_pcm_uframes_t offset)

src/modules/module-protocol-pulse/internal.h

@@ -52,7 +52,7 @@ struct impl {
 	struct pw_properties *props;
 	void *dbus_name;
 
-	struct ratelimit rate_limit;
+	struct spa_ratelimit rate_limit;
 
 	struct spa_hook_list hooks;
 	struct spa_list servers;

src/modules/module-protocol-pulse/stream.c

@@ -216,10 +216,11 @@ int stream_send_underflow(struct stream *stream, int64_t offset)
 	struct client *client = stream->client;
 	struct impl *impl = client->impl;
 	struct message *reply;
+	int missed;
 
-	if (ratelimit_test(&impl->rate_limit, stream->timestamp, SPA_LOG_LEVEL_INFO)) {
-		pw_log_info("[%s]: UNDERFLOW channel:%u offset:%" PRIi64,
-			    client->name, stream->channel, offset);
+	if ((missed = spa_ratelimit_test(&impl->rate_limit, stream->timestamp)) >= 0) {
+		pw_log_info("[%s]: UNDERFLOW channel:%u offset:%" PRIi64" (%d missed)",
+			    client->name, stream->channel, offset, missed);
 	}
 
 	reply = message_alloc(impl, -1, 0);

src/modules/module-pulse-tunnel.c

@@ -21,6 +21,7 @@
 #include <spa/utils/json.h>
 #include <spa/utils/ringbuffer.h>
 #include <spa/utils/dll.h>
+#include <spa/utils/ratelimit.h>
 #include <spa/debug/types.h>
 #include <spa/pod/builder.h>
 #include <spa/param/audio/format-utils.h>
@@ -170,7 +171,7 @@ struct impl {
 	pa_stream *pa_stream;
 	uint32_t pa_index;
 
-	struct ratelimit rate_limit;
+	struct spa_ratelimit rate_limit;
 
 	uint32_t target_latency;
 	uint32_t current_latency;
@@ -669,19 +670,22 @@ static void stream_underflow_cb(pa_stream *s, void *userdata)
 {
 	struct impl *impl = userdata;
 	struct timespec ts;
+	int missed;
 
 	clock_gettime(CLOCK_MONOTONIC, &ts);
-	if (ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts), SPA_LOG_LEVEL_WARN))
-		pw_log_warn("underflow");
+	if ((missed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0)
+		pw_log_warn("underflow (%d missed)", missed);
 	impl->resync = true;
 }
 static void stream_overflow_cb(pa_stream *s, void *userdata)
 {
 	struct impl *impl = userdata;
 	struct timespec ts;
+	int missed;
+
 	clock_gettime(CLOCK_MONOTONIC, &ts);
-	if (ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts), SPA_LOG_LEVEL_WARN))
-		pw_log_warn("overflow");
+	if ((missed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0)
+		pw_log_warn("overflow (%d missed)", missed);
 	impl->resync = true;
 }
 

src/pipewire/impl-node.c

@@ -1095,8 +1095,9 @@ static void check_states(struct pw_impl_node *driver, uint64_t nsec)
 	struct pw_node_activation *na = driver->rt.target.activation;
 	struct spa_io_clock *cl = &na->position.clock;
 	enum spa_log_level level = SPA_LOG_LEVEL_DEBUG;
+	int missed;
 
-	if (ratelimit_test(&driver->rt.rate_limit, nsec, SPA_LOG_LEVEL_DEBUG))
+	if ((missed = spa_ratelimit_test(&driver->rt.rate_limit, nsec)) >= 0)
 		level = SPA_LOG_LEVEL_INFO;
 
 	spa_list_for_each(t, &driver->rt.target_list, link) {
@@ -1110,10 +1111,11 @@ static void check_states(struct pw_impl_node *driver, uint64_t nsec)
 		    a->status == PW_NODE_ACTIVATION_AWAKE) {
 			update_xrun_stats(a, nsec / 1000, 0);
 
-			pw_log(level, "(%s-%u) client too slow! rate:%u/%u pos:%"PRIu64" status:%s",
+			pw_log(level, "(%s-%u) client too slow! rate:%u/%u pos:%"PRIu64" status:%s (%u missed)",
 				t->name, t->id,
 				(uint32_t)(cl->rate.num * cl->duration), cl->rate.denom,
-				cl->position, str_status(a->status));
+				cl->position, str_status(a->status),
+				missed);
 		}
 		pw_log_debug("(%s-%u) state:%p pending:%d/%d s:%"PRIu64" a:%"PRIu64" f:%"PRIu64
 				" waiting:%"PRIu64" process:%"PRIu64" status:%s sync:%d",
@@ -1881,10 +1883,11 @@ static int node_xrun(void *data, uint64_t trigger, uint64_t delay, struct spa_po
 	struct pw_node_activation *da = this->rt.driver_target.activation;
 	struct spa_system *data_system = this->data_system;
 	uint64_t nsec = get_time_ns(data_system);
+	int missed;
 
 	update_xrun_stats(a, trigger, delay);
 
-	if (ratelimit_test(&this->rt.rate_limit, nsec, SPA_LOG_LEVEL_INFO)) {
+	if ((missed = spa_ratelimit_test(&this->rt.rate_limit, nsec)) >= 0) {
 		struct spa_fraction rate;
 		if (da) {
 			struct spa_io_clock *cl = &da->position.clock;
@@ -1894,10 +1897,11 @@ static int node_xrun(void *data, uint64_t trigger, uint64_t delay, struct spa_po
 			rate = SPA_FRACTION(0,0);
 		}
 		pw_log_info("(%s-%d) XRun! rate:%u/%u count:%u time:%"PRIu64
-				" delay:%"PRIu64" max:%"PRIu64,
+				" delay:%"PRIu64" max:%"PRIu64" (%d missed)",
 				this->name, this->info.id,
 				rate.num, rate.denom, a->xrun_count,
-				trigger, delay, a->max_delay);
+				trigger, delay, a->max_delay,
+				missed);
 	}
 
 	pw_context_driver_emit_xrun(this->context, this);

src/pipewire/private.h

@@ -17,6 +17,7 @@ extern "C" {
 #include <spa/support/plugin.h>
 #include <spa/pod/builder.h>
 #include <spa/param/latency-utils.h>
+#include <spa/utils/ratelimit.h>
 #include <spa/utils/result.h>
 #include <spa/utils/type-info.h>
 
@@ -53,29 +54,6 @@ struct settings {
 	uint32_t clock_force_quantum;		/* force a quantum */
 };
 
-struct ratelimit {
-	uint64_t interval;
-	uint64_t begin;
-	unsigned burst;
-	unsigned n_printed, n_missed;
-};
-
-static inline bool ratelimit_test(struct ratelimit *r, uint64_t now, enum spa_log_level level)
-{
-	if (r->begin + r->interval < now) {
-		if (r->n_missed)
-			pw_log(level, "%u events suppressed", r->n_missed);
-		r->begin = now;
-		r->n_printed = 0;
-		r->n_missed = 0;
-	} else if (r->n_printed >= r->burst) {
-		r->n_missed++;
-		return false;
-	}
-	r->n_printed++;
-	return true;
-}
-
 #define MAX_PARAMS	32
 
 struct pw_param {
@@ -795,7 +773,7 @@ struct pw_impl_node {
 							   driver */
 		struct spa_list driver_link;		/* our link in driver */
 
-		struct ratelimit rate_limit;
+		struct spa_ratelimit rate_limit;
 	} rt;
 	struct spa_fraction target_rate;
 	uint64_t target_quantum;