From dc07c2321b208dae28908980a399051324d2ee9d Mon Sep 17 00:00:00 2001 From: Wim Taymans Date: Tue, 11 Jul 2023 19:25:13 +0200 Subject: [PATCH] spa: add spa_ratelimit --- spa/include/spa/utils/ratelimit.h | 42 ++++++++++++++++++++ spa/plugins/alsa/alsa-pcm.c | 12 +++--- spa/plugins/alsa/alsa-pcm.h | 26 +----------- src/modules/module-protocol-pulse/internal.h | 2 +- src/modules/module-protocol-pulse/stream.c | 7 ++-- src/modules/module-pulse-tunnel.c | 14 ++++--- src/pipewire/impl-node.c | 16 +++++--- src/pipewire/private.h | 26 +----------- 8 files changed, 76 insertions(+), 69 deletions(-) create mode 100644 spa/include/spa/utils/ratelimit.h diff --git a/spa/include/spa/utils/ratelimit.h b/spa/include/spa/utils/ratelimit.h new file mode 100644 index 000000000..9f0d7a481 --- /dev/null +++ b/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 + +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 */ diff --git a/spa/plugins/alsa/alsa-pcm.c b/spa/plugins/alsa/alsa-pcm.c index b2338fcc1..3a944320e 100644 --- a/spa/plugins/alsa/alsa-pcm.c +++ b/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, diff --git a/spa/plugins/alsa/alsa-pcm.h b/spa/plugins/alsa/alsa-pcm.h index 8b893bb91..93507523e 100644 --- a/spa/plugins/alsa/alsa-pcm.h +++ b/spa/plugins/alsa/alsa-pcm.h @@ -21,6 +21,7 @@ extern "C" { #include #include #include +#include #include #include @@ -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) diff --git a/src/modules/module-protocol-pulse/internal.h b/src/modules/module-protocol-pulse/internal.h index d53c49573..3cf5ac603 100644 --- a/src/modules/module-protocol-pulse/internal.h +++ b/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; diff --git a/src/modules/module-protocol-pulse/stream.c b/src/modules/module-protocol-pulse/stream.c index 7ed891154..0bdfe1209 100644 --- a/src/modules/module-protocol-pulse/stream.c +++ b/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); diff --git a/src/modules/module-pulse-tunnel.c b/src/modules/module-pulse-tunnel.c index 000d7c1b1..38fefc9e4 100644 --- a/src/modules/module-pulse-tunnel.c +++ b/src/modules/module-pulse-tunnel.c @@ -21,6 +21,7 @@ #include #include #include +#include #include #include #include @@ -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; } diff --git a/src/pipewire/impl-node.c b/src/pipewire/impl-node.c index 294c959f6..ae10cf97c 100644 --- a/src/pipewire/impl-node.c +++ b/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); diff --git a/src/pipewire/private.h b/src/pipewire/private.h index 10573e2b3..eff5cd614 100644 --- a/src/pipewire/private.h +++ b/src/pipewire/private.h @@ -17,6 +17,7 @@ extern "C" { #include #include #include +#include #include #include @@ -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;