From ef39576150fd7c112fdc45493596fa4791ddb68d Mon Sep 17 00:00:00 2001 From: Wim Taymans Date: Wed, 21 Sep 2022 15:52:24 +0200 Subject: [PATCH] alsa: rate limit some warnings --- spa/plugins/alsa/alsa-pcm.c | 52 +++++++++++++++++++++++++------------ spa/plugins/alsa/alsa-pcm.h | 26 ++++++++++++++++++- 2 files changed, 60 insertions(+), 18 deletions(-) diff --git a/spa/plugins/alsa/alsa-pcm.c b/spa/plugins/alsa/alsa-pcm.c index 6bcb7d851..5f851bebe 100644 --- a/spa/plugins/alsa/alsa-pcm.c +++ b/spa/plugins/alsa/alsa-pcm.c @@ -511,6 +511,9 @@ int spa_alsa_init(struct state *state, const struct spa_dict *info) } CHECK(snd_output_stdio_attach(&state->output, state->log_file, 0), "attach failed"); + state->rate_limit.interval = 2 * SPA_NSEC_PER_SEC; + state->rate_limit.burst = 1; + return 0; } @@ -1779,15 +1782,17 @@ recover: static int get_avail(struct state *state, uint64_t current_time) { - int res; + int res, missed; snd_pcm_sframes_t avail; if (SPA_UNLIKELY((avail = snd_pcm_avail(state->hndl)) < 0)) { if ((res = alsa_recover(state, avail)) < 0) return res; if ((avail = snd_pcm_avail(state->hndl)) < 0) { - spa_log_warn(state->log, "%s: snd_pcm_avail after recover: %s", - state->props.device, snd_strerror(avail)); + if ((missed = 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)); + } avail = state->threshold * 2; } } else { @@ -1799,7 +1804,7 @@ static int get_avail(struct state *state, uint64_t current_time) #if 0 static int get_avail_htimestamp(struct state *state, uint64_t current_time) { - int res; + int res, missed; snd_pcm_uframes_t avail; snd_htimestamp_t tstamp; uint64_t then; @@ -1808,8 +1813,10 @@ static int get_avail_htimestamp(struct state *state, uint64_t current_time) if ((res = alsa_recover(state, avail)) < 0) return res; if ((res = snd_pcm_htimestamp(state->hndl, &avail, &tstamp)) < 0) { - spa_log_warn(state->log, "%s: snd_pcm_htimestamp error: %s", - state->props.device, snd_strerror(res)); + if ((missed = 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)); + } avail = state->threshold * 2; } } else { @@ -1985,7 +1992,7 @@ int spa_alsa_write(struct state *state) const snd_pcm_channel_area_t *my_areas; snd_pcm_uframes_t written, frames, offset, off, to_write, total_written, max_write; snd_pcm_sframes_t commitres; - int res = 0; + int res = 0, missed; size_t frame_size = state->frame_size; check_position_config(state); @@ -2005,13 +2012,19 @@ int spa_alsa_write(struct state *state) return res; if (SPA_UNLIKELY(state->alsa_sync)) { + enum spa_log_level lev; + if (SPA_UNLIKELY(state->alsa_sync_warning)) { - spa_log_warn(state->log, "%s: follower delay:%ld target:%ld thr:%u, resync", - state->props.device, delay, target, state->threshold); + lev = SPA_LOG_LEVEL_WARN; state->alsa_sync_warning = false; } else - spa_log_info(state->log, "%s: follower delay:%ld target:%ld thr:%u, resync", - state->props.device, delay, target, state->threshold); + lev = SPA_LOG_LEVEL_INFO; + + if ((missed = 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); + } if (delay > target) snd_pcm_rewind(state->hndl, delay - target); @@ -2212,7 +2225,7 @@ int spa_alsa_read(struct state *state) const snd_pcm_channel_area_t *my_areas; snd_pcm_uframes_t read, frames, offset; snd_pcm_sframes_t commitres; - int res = 0; + int res = 0, missed; check_position_config(state); @@ -2221,7 +2234,6 @@ int spa_alsa_read(struct state *state) if (state->following && state->alsa_started) { uint64_t current_time; snd_pcm_uframes_t avail, delay, target; - uint32_t threshold = state->threshold; current_time = state->position->clock.nsec; @@ -2234,13 +2246,19 @@ int spa_alsa_read(struct state *state) return res; if (state->alsa_sync) { + enum spa_log_level lev; + if (SPA_UNLIKELY(state->alsa_sync_warning)) { - spa_log_warn(state->log, "%s: follower delay:%lu target:%lu thr:%u, resync", - state->props.device, delay, target, threshold); + lev = SPA_LOG_LEVEL_WARN; state->alsa_sync_warning = false; } else - spa_log_info(state->log, "%s: follower delay:%lu target:%lu thr:%u, resync", - state->props.device, delay, target, threshold); + lev = SPA_LOG_LEVEL_INFO; + + if ((missed = 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); + } if (delay < target) max_read = target - delay; diff --git a/spa/plugins/alsa/alsa-pcm.h b/spa/plugins/alsa/alsa-pcm.h index 91385f40d..c630de3ac 100644 --- a/spa/plugins/alsa/alsa-pcm.h +++ b/spa/plugins/alsa/alsa-pcm.h @@ -87,7 +87,6 @@ struct channel_map { uint32_t pos[SPA_AUDIO_MAX_CHANNELS]; }; - struct card { struct spa_list link; int ref; @@ -98,6 +97,13 @@ 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; @@ -107,6 +113,7 @@ struct state { struct spa_loop *data_loop; FILE *log_file; + struct ratelimit rate_limit; uint32_t card_index; struct card *card; @@ -342,6 +349,23 @@ 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; +} + + #ifdef __cplusplus } /* extern "C" */ #endif