ratelimit: missed -> suppressed

To avoid confusing with missed samples.
This commit is contained in:
Wim Taymans 2023-09-08 12:18:23 +02:00
parent 1837654a4b
commit 016d15e598
6 changed files with 50 additions and 50 deletions

View file

@ -17,23 +17,23 @@ struct spa_ratelimit {
uint64_t begin; uint64_t begin;
unsigned burst; unsigned burst;
unsigned n_printed; unsigned n_printed;
unsigned n_missed; unsigned n_suppressed;
}; };
static inline int spa_ratelimit_test(struct spa_ratelimit *r, uint64_t now) static inline int spa_ratelimit_test(struct spa_ratelimit *r, uint64_t now)
{ {
unsigned missed = 0; unsigned suppressed = 0;
if (r->begin + r->interval < now) { if (r->begin + r->interval < now) {
missed = r->n_missed; suppressed = r->n_suppressed;
r->begin = now; r->begin = now;
r->n_printed = 0; r->n_printed = 0;
r->n_missed = 0; r->n_suppressed = 0;
} else if (r->n_printed >= r->burst) { } else if (r->n_printed >= r->burst) {
r->n_missed++; r->n_suppressed++;
return -1; return -1;
} }
r->n_printed++; r->n_printed++;
return missed; return suppressed;
} }
#ifdef __cplusplus #ifdef __cplusplus

View file

@ -1994,16 +1994,16 @@ recover:
static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes_t *delay) static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes_t *delay)
{ {
int res, missed; int res, suppressed;
snd_pcm_sframes_t avail; snd_pcm_sframes_t avail;
if (SPA_UNLIKELY((avail = snd_pcm_avail(state->hndl)) < 0)) { if (SPA_UNLIKELY((avail = snd_pcm_avail(state->hndl)) < 0)) {
if ((res = alsa_recover(state, avail)) < 0) if ((res = alsa_recover(state, avail)) < 0)
return res; return res;
if ((avail = snd_pcm_avail(state->hndl)) < 0) { if ((avail = snd_pcm_avail(state->hndl)) < 0) {
if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_warn(state->log, "%s: (%d missed) snd_pcm_avail after recover: %s", spa_log_warn(state->log, "%s: (%d suppressed) snd_pcm_avail after recover: %s",
state->props.device, missed, snd_strerror(avail)); state->props.device, suppressed, snd_strerror(avail));
} }
avail = state->threshold * 2; avail = state->threshold * 2;
} }
@ -2018,9 +2018,9 @@ static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes
uint64_t then; uint64_t then;
if ((res = snd_pcm_htimestamp(state->hndl, &havail, &tstamp)) < 0) { if ((res = snd_pcm_htimestamp(state->hndl, &havail, &tstamp)) < 0) {
if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_warn(state->log, "%s: (%d missed) snd_pcm_htimestamp error: %s", spa_log_warn(state->log, "%s: (%d suppressed) snd_pcm_htimestamp error: %s",
state->props.device, missed, snd_strerror(res)); state->props.device, suppressed, snd_strerror(res));
} }
return avail; return avail;
} }
@ -2046,9 +2046,9 @@ static int get_avail(struct state *state, uint64_t current_time, snd_pcm_uframes
state->htimestamp_error = 0; state->htimestamp_error = 0;
state->htimestamp = false; state->htimestamp = false;
} }
else if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { else if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_warn(state->log, "%s: (%d missed) impossible htimestamp diff:%"PRIi64, spa_log_warn(state->log, "%s: (%d suppressed) impossible htimestamp diff:%"PRIi64,
state->props.device, missed, diff); state->props.device, suppressed, diff);
} }
} }
} }
@ -2253,7 +2253,7 @@ int spa_alsa_write(struct state *state)
const snd_pcm_channel_area_t *my_areas; const snd_pcm_channel_area_t *my_areas;
snd_pcm_uframes_t written, frames, offset, off, to_write, total_written, max_write; snd_pcm_uframes_t written, frames, offset, off, to_write, total_written, max_write;
snd_pcm_sframes_t commitres; snd_pcm_sframes_t commitres;
int res, missed; int res, suppressed;
size_t frame_size = state->frame_size; size_t frame_size = state->frame_size;
if ((res = check_position_config(state)) < 0) if ((res = check_position_config(state)) < 0)
@ -2281,11 +2281,11 @@ int spa_alsa_write(struct state *state)
else else
lev = SPA_LOG_LEVEL_INFO; lev = SPA_LOG_LEVEL_INFO;
if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_lev(state->log, lev, "%s: follower avail:%lu delay:%ld " spa_log_lev(state->log, lev, "%s: follower avail:%lu delay:%ld "
"target:%ld thr:%u, resync (%d missed)", "target:%ld thr:%u, resync (%d suppressed)",
state->props.device, avail, delay, state->props.device, avail, delay,
target, state->threshold, missed); target, state->threshold, suppressed);
} }
if (avail > target) if (avail > target)
@ -2491,7 +2491,7 @@ int spa_alsa_read(struct state *state)
const snd_pcm_channel_area_t *my_areas; const snd_pcm_channel_area_t *my_areas;
snd_pcm_uframes_t read, frames, offset; snd_pcm_uframes_t read, frames, offset;
snd_pcm_sframes_t commitres; snd_pcm_sframes_t commitres;
int res, missed; int res, suppressed;
if ((res = check_position_config(state)) < 0) if ((res = check_position_config(state)) < 0)
return res; return res;
@ -2518,10 +2518,10 @@ int spa_alsa_read(struct state *state)
else else
lev = SPA_LOG_LEVEL_INFO; lev = SPA_LOG_LEVEL_INFO;
if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_lev(state->log, lev, "%s: follower delay:%ld target:%ld thr:%u, " spa_log_lev(state->log, lev, "%s: follower delay:%ld target:%ld thr:%u, "
"resync (%d missed)", state->props.device, delay, "resync (%d suppressed)", state->props.device, delay,
target, state->threshold, missed); target, state->threshold, suppressed);
} }
if (avail < target) if (avail < target)
@ -2700,7 +2700,7 @@ static void alsa_wakeup_event(struct spa_source *source)
struct state *state = source->data; struct state *state = source->data;
snd_pcm_uframes_t avail, delay, target; snd_pcm_uframes_t avail, delay, target;
uint64_t expire, current_time; uint64_t expire, current_time;
int res, missed; int res, suppressed;
if (SPA_UNLIKELY(state->disable_tsched)) { if (SPA_UNLIKELY(state->disable_tsched)) {
/* ALSA poll fds need to be "demangled" to know whether it's a real wakeup */ /* ALSA poll fds need to be "demangled" to know whether it's a real wakeup */
@ -2772,12 +2772,12 @@ done:
if (!state->disable_tsched && if (!state->disable_tsched &&
(state->next_time > current_time + SPA_NSEC_PER_SEC || (state->next_time > current_time + SPA_NSEC_PER_SEC ||
current_time > state->next_time + SPA_NSEC_PER_SEC)) { current_time > state->next_time + SPA_NSEC_PER_SEC)) {
if ((missed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) { if ((suppressed = spa_ratelimit_test(&state->rate_limit, current_time)) >= 0) {
spa_log_error(state->log, "%s: impossible timeout %lu %lu %lu %" spa_log_error(state->log, "%s: impossible timeout %lu %lu %lu %"
PRIu64" %"PRIu64" %"PRIi64" %d %"PRIi64" (%d missed)", PRIu64" %"PRIu64" %"PRIi64" %d %"PRIi64" (%d suppressed)",
state->props.device, avail, delay, target, state->props.device, avail, delay, target,
current_time, state->next_time, state->next_time - current_time, current_time, state->next_time, state->next_time - current_time,
state->threshold, state->sample_count, missed); state->threshold, state->sample_count, suppressed);
} }
state->next_time = current_time + state->threshold * 1e9 / state->rate; state->next_time = current_time + state->threshold * 1e9 / state->rate;
} }

View file

@ -2740,7 +2740,7 @@ static int impl_node_process(void *object)
struct buffer *buf, *out_bufs[MAX_PORTS]; struct buffer *buf, *out_bufs[MAX_PORTS];
struct spa_data *bd; struct spa_data *bd;
struct dir *dir; struct dir *dir;
int tmp = 0, res = 0, missed; int tmp = 0, res = 0, suppressed;
bool in_passthrough, mix_passthrough, resample_passthrough, out_passthrough; bool in_passthrough, mix_passthrough, resample_passthrough, out_passthrough;
bool in_avail = false, flush_in = false, flush_out = false; bool in_avail = false, flush_in = false, flush_out = false;
bool draining = false, in_empty = this->out_offset == 0; bool draining = false, in_empty = this->out_offset == 0;
@ -2908,9 +2908,9 @@ static int impl_node_process(void *object)
buf = peek_buffer(this, port); buf = peek_buffer(this, port);
if (buf == NULL && port->n_buffers > 0 && if (buf == NULL && port->n_buffers > 0 &&
(missed = spa_ratelimit_test(&this->rate_limit, current_time)) >= 0) { (suppressed = spa_ratelimit_test(&this->rate_limit, current_time)) >= 0) {
spa_log_warn(this->log, "%p: (%d missed) out of buffers on port %d %d", spa_log_warn(this->log, "%p: (%d suppressed) out of buffers on port %d %d",
this, missed, port->id, port->n_buffers); this, suppressed, port->id, port->n_buffers);
} }
} }
out_bufs[i] = buf; out_bufs[i] = buf;

View file

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

View file

@ -672,22 +672,22 @@ static void stream_underflow_cb(pa_stream *s, void *userdata)
{ {
struct impl *impl = userdata; struct impl *impl = userdata;
struct timespec ts; struct timespec ts;
int missed; int suppressed;
clock_gettime(CLOCK_MONOTONIC, &ts); clock_gettime(CLOCK_MONOTONIC, &ts);
if ((missed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0) if ((suppressed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0)
pw_log_warn("underflow (%d missed)", missed); pw_log_warn("underflow (%d suppressed)", suppressed);
impl->resync = true; impl->resync = true;
} }
static void stream_overflow_cb(pa_stream *s, void *userdata) static void stream_overflow_cb(pa_stream *s, void *userdata)
{ {
struct impl *impl = userdata; struct impl *impl = userdata;
struct timespec ts; struct timespec ts;
int missed; int suppressed;
clock_gettime(CLOCK_MONOTONIC, &ts); clock_gettime(CLOCK_MONOTONIC, &ts);
if ((missed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0) if ((suppressed = spa_ratelimit_test(&impl->rate_limit, SPA_TIMESPEC_TO_NSEC(&ts))) >= 0)
pw_log_warn("overflow (%d missed)", missed); pw_log_warn("overflow (%d suppressed)", suppressed);
impl->resync = true; impl->resync = true;
} }

View file

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